Repository: netty/netty
Issue: some problems with netty debug log
Labels: defect

### Expected behavior
netty can print rigth debug log with its parameter.
### Actual behavior
can not print its parameter.
[DEBUG][2018-11-08 16:26:58,872][io.netty.util.internal.logging.InternalLoggerFactory]Using SLF4J as the default logging framework
[DEBUG][2018-11-08 16:26:58,882][io.netty.channel.MultithreadEventLoopGroup]-Dio.netty.eventLoopThreads: {}
[DEBUG][2018-11-08 16:26:58,913][io.netty.channel.nio.NioEventLoop]-Dio.netty.noKeySetOptimization: {}
[DEBUG][2018-11-08 16:26:58,913][io.netty.channel.nio.NioEventLoop]-Dio.netty.selectorAutoRebuildThreshold: {}
### Steps to reproduce
problem happpened when using slf4j-log4j12 for logger.  when i just  use log4j it is ok.  How to solve? 
<dependency>
			<groupId>org.slf4j</groupId>
			<artifactId>slf4j-log4j12</artifactId>
			<version>1.7.25</version>
		</dependency>
### Minimal yet complete reproducer code (or URL to code)

### Netty version
4.1.31
### JVM version (e.g. `java -version`)
1.8
### OS version (e.g. `uname -a`)


Issue comments:
Should be fixed by #8595

Pull request review comments:
Presumably there's no need to also pass the args now? If so it would be better to pass null for the last arg to avoid varargs array allocation.
from other implementations I think you still should pass the args. 
I still don't follow (sorry I'm probably missing something) ... the additional args are only passed for the purpose of later substitution into the message, but now the substitution is done upfront. So the message passed won't have `{}` corresponding to the args..?
@njhill when looking at other implementation they all forwarded the "args", so I did the same as I thought maybe they are used somehow later on. I think at worse you have one more alloc but not passing these down may produce other side-effects depending on the underlying implementations.

That said maybe you are right and we should just not do it. 



@njhill PTAL again... I think this addresses your concern and is also cleaner :)
@normanmaurer LGTM, I was about to suggest something similar :)
Not part of this PR but I think methods like this one don't need the `if (isXxxEnabled())` right?

Patch that resolved the issue:
diff --git a/common/src/main/java/io/netty/util/internal/logging/LocationAwareSlf4JLogger.java b/common/src/main/java/io/netty/util/internal/logging/LocationAwareSlf4JLogger.java
index 13073b02b41..33eb705a8f0 100644
--- a/common/src/main/java/io/netty/util/internal/logging/LocationAwareSlf4JLogger.java
+++ b/common/src/main/java/io/netty/util/internal/logging/LocationAwareSlf4JLogger.java
@@ -28,7 +28,7 @@ final class LocationAwareSlf4JLogger extends AbstractInternalLogger {
     // IMPORTANT: All our log methods first check if the log level is enabled before call the wrapped
     // LocationAwareLogger.log(...) method. This is done to reduce GC creation that is caused by varargs.
 
-    private static final String FQCN = LocationAwareSlf4JLogger.class.getName();
+    static final String FQCN = LocationAwareSlf4JLogger.class.getName();
     private static final long serialVersionUID = -8292030083201538180L;
 
     private final transient LocationAwareLogger logger;
@@ -38,12 +38,16 @@ final class LocationAwareSlf4JLogger extends AbstractInternalLogger {
         this.logger = logger;
     }
 
-    private void log(final int level, final String message, final Object... params) {
-        logger.log(null, FQCN, level, message, params, null);
+    private void log(final int level, final String message) {
+        logger.log(null, FQCN, level, message, null, null);
     }
 
-    private void log(final int level, final String message, Throwable throwable, final Object... params) {
-        logger.log(null, FQCN, level, message, params, throwable);
+    private void log(final int level, final String message, Throwable cause) {
+        logger.log(null, FQCN, level, message, null, cause);
+    }
+
+    private void log(final int level, final org.slf4j.helpers.FormattingTuple tuple) {
+        logger.log(null, FQCN, level, tuple.getMessage(), tuple.getArgArray(), tuple.getThrowable());
     }
 
     @Override
@@ -54,28 +58,28 @@ public boolean isTraceEnabled() {
     @Override
     public void trace(String msg) {
         if (isTraceEnabled()) {
-            log(TRACE_INT, msg, null);
+            log(TRACE_INT, msg);
         }
     }
 
     @Override
     public void trace(String format, Object arg) {
         if (isTraceEnabled()) {
-            log(TRACE_INT, format, arg);
+            log(TRACE_INT, org.slf4j.helpers.MessageFormatter.format(format, arg));
         }
     }
 
     @Override
     public void trace(String format, Object argA, Object argB) {
         if (isTraceEnabled()) {
-            log(TRACE_INT, format, argA, argB);
+            log(TRACE_INT, org.slf4j.helpers.MessageFormatter.format(format, argA, argB));
         }
     }
 
     @Override
     public void trace(String format, Object... argArray) {
         if (isTraceEnabled()) {
-            log(TRACE_INT, format, argArray);
+            log(TRACE_INT, org.slf4j.helpers.MessageFormatter.format(format, argArray));
         }
     }
 
@@ -101,21 +105,21 @@ public void debug(String msg) {
     @Override
     public void debug(String format, Object arg) {
         if (isDebugEnabled()) {
-            log(DEBUG_INT, format, arg);
+            log(DEBUG_INT, org.slf4j.helpers.MessageFormatter.format(format, arg));
         }
     }
 
     @Override
     public void debug(String format, Object argA, Object argB) {
         if (isDebugEnabled()) {
-            log(DEBUG_INT, format, argA, argB);
+            log(DEBUG_INT, org.slf4j.helpers.MessageFormatter.format(format, argA, argB));
         }
     }
 
     @Override
     public void debug(String format, Object... argArray) {
         if (isDebugEnabled()) {
-            log(DEBUG_INT, format, argArray);
+            log(DEBUG_INT, org.slf4j.helpers.MessageFormatter.format(format, argArray));
         }
     }
 
@@ -141,21 +145,21 @@ public void info(String msg) {
     @Override
     public void info(String format, Object arg) {
         if (isInfoEnabled()) {
-            log(INFO_INT, format, arg);
+            log(INFO_INT, org.slf4j.helpers.MessageFormatter.format(format, arg));
         }
     }
 
     @Override
     public void info(String format, Object argA, Object argB) {
         if (isInfoEnabled()) {
-            log(INFO_INT, format, argA, argB);
+            log(INFO_INT, org.slf4j.helpers.MessageFormatter.format(format, argA, argB));
         }
     }
 
     @Override
     public void info(String format, Object... argArray) {
         if (isInfoEnabled()) {
-            log(INFO_INT, format, argArray);
+            log(INFO_INT, org.slf4j.helpers.MessageFormatter.format(format, argArray));
         }
     }
 
@@ -181,21 +185,21 @@ public void warn(String msg) {
     @Override
     public void warn(String format, Object arg) {
         if (isWarnEnabled()) {
-            log(WARN_INT, format, arg);
+            log(WARN_INT, org.slf4j.helpers.MessageFormatter.format(format, arg));
         }
     }
 
     @Override
     public void warn(String format, Object... argArray) {
         if (isWarnEnabled()) {
-            log(WARN_INT, format, argArray);
+            log(WARN_INT, org.slf4j.helpers.MessageFormatter.format(format, argArray));
         }
     }
 
     @Override
     public void warn(String format, Object argA, Object argB) {
         if (isWarnEnabled()) {
-            log(WARN_INT, format, argA, argB);
+            log(WARN_INT, org.slf4j.helpers.MessageFormatter.format(format, argA, argB));
         }
     }
 
@@ -221,21 +225,21 @@ public void error(String msg) {
     @Override
     public void error(String format, Object arg) {
         if (isErrorEnabled()) {
-            log(ERROR_INT, format, arg);
+            log(ERROR_INT, org.slf4j.helpers.MessageFormatter.format(format, arg));
         }
     }
 
     @Override
     public void error(String format, Object argA, Object argB) {
         if (isErrorEnabled()) {
-            log(ERROR_INT, format, argA, argB);
+            log(ERROR_INT, org.slf4j.helpers.MessageFormatter.format(format, argA, argB));
         }
     }
 
     @Override
     public void error(String format, Object... argArray) {
         if (isErrorEnabled()) {
-            log(ERROR_INT, format, argArray);
+            log(ERROR_INT, org.slf4j.helpers.MessageFormatter.format(format, argArray));
         }
     }
 


Test patch:
diff --git a/common/src/test/java/io/netty/util/internal/logging/Slf4JLoggerFactoryTest.java b/common/src/test/java/io/netty/util/internal/logging/Slf4JLoggerFactoryTest.java
index 6b3cd850158..8cb2f84f7a9 100644
--- a/common/src/test/java/io/netty/util/internal/logging/Slf4JLoggerFactoryTest.java
+++ b/common/src/test/java/io/netty/util/internal/logging/Slf4JLoggerFactoryTest.java
@@ -16,13 +16,19 @@
 package io.netty.util.internal.logging;
 
 import org.junit.Test;
+import org.mockito.ArgumentCaptor;
+import org.mockito.ArgumentMatchers;
 import org.slf4j.Logger;
+import org.slf4j.Marker;
 import org.slf4j.spi.LocationAwareLogger;
 
+import java.util.Iterator;
+
 import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertFalse;
 import static org.junit.Assert.assertTrue;
-import static org.mockito.Mockito.mock;
-import static org.mockito.Mockito.when;
+import static org.mockito.ArgumentMatchers.*;
+import static org.mockito.Mockito.*;
 
 public class Slf4JLoggerFactoryTest {
 
@@ -50,4 +56,61 @@ public void testCreationLocationAwareLogger() {
         assertTrue(internalLogger instanceof LocationAwareSlf4JLogger);
         assertEquals("testlogger", internalLogger.name());
     }
+
+    @Test
+    public void testFormatMessage() {
+        ArgumentCaptor<String> captor = ArgumentCaptor.forClass(String.class);
+        LocationAwareLogger logger = mock(LocationAwareLogger.class);
+        when(logger.isDebugEnabled()).thenReturn(true);
+        when(logger.isErrorEnabled()).thenReturn(true);
+        when(logger.isInfoEnabled()).thenReturn(true);
+        when(logger.isTraceEnabled()).thenReturn(true);
+        when(logger.isWarnEnabled()).thenReturn(true);
+        when(logger.getName()).thenReturn("testlogger");
+
+        InternalLogger internalLogger = Slf4JLoggerFactory.wrapLogger(logger);
+        internalLogger.debug("{}", "debug");
+        internalLogger.debug("{} {}", "debug1", "debug2");
+
+        internalLogger.error("{}", "error");
+        internalLogger.error("{} {}", "error1", "error2");
+
+        internalLogger.info("{}", "info");
+        internalLogger.info("{} {}", "info1", "info2");
+
+        internalLogger.trace("{}", "trace");
+        internalLogger.trace("{} {}", "trace1", "trace2");
+
+        internalLogger.warn("{}", "warn");
+        internalLogger.warn("{} {}", "warn1", "warn2");
+
+        verify(logger, times(2)).log(ArgumentMatchers.<Marker>isNull(), eq(LocationAwareSlf4JLogger.FQCN),
+                eq(LocationAwareLogger.DEBUG_INT), captor.capture(), any(Object[].class),
+                ArgumentMatchers.<Throwable>isNull());
+        verify(logger, times(2)).log(ArgumentMatchers.<Marker>isNull(), eq(LocationAwareSlf4JLogger.FQCN),
+                eq(LocationAwareLogger.ERROR_INT), captor.capture(), any(Object[].class),
+                ArgumentMatchers.<Throwable>isNull());
+        verify(logger, times(2)).log(ArgumentMatchers.<Marker>isNull(), eq(LocationAwareSlf4JLogger.FQCN),
+                eq(LocationAwareLogger.INFO_INT), captor.capture(), any(Object[].class),
+                ArgumentMatchers.<Throwable>isNull());
+        verify(logger, times(2)).log(ArgumentMatchers.<Marker>isNull(), eq(LocationAwareSlf4JLogger.FQCN),
+                eq(LocationAwareLogger.TRACE_INT), captor.capture(), any(Object[].class),
+                ArgumentMatchers.<Throwable>isNull());
+        verify(logger, times(2)).log(ArgumentMatchers.<Marker>isNull(), eq(LocationAwareSlf4JLogger.FQCN),
+                eq(LocationAwareLogger.WARN_INT), captor.capture(), any(Object[].class),
+                ArgumentMatchers.<Throwable>isNull());
+
+        Iterator<String> logMessages = captor.getAllValues().iterator();
+        assertEquals("debug", logMessages.next());
+        assertEquals("debug1 debug2", logMessages.next());
+        assertEquals("error", logMessages.next());
+        assertEquals("error1 error2", logMessages.next());
+        assertEquals("info", logMessages.next());
+        assertEquals("info1 info2", logMessages.next());
+        assertEquals("trace", logMessages.next());
+        assertEquals("trace1 trace2", logMessages.next());
+        assertEquals("warn", logMessages.next());
+        assertEquals("warn1 warn2", logMessages.next());
+        assertFalse(logMessages.hasNext());
+    }
 }