LocationAwareSlf4jLogger does not correctly format log message. (#8595)

Motivation:

We did miss to use MessageFormatter inside LocationAwareSlf4jLogger and so {} was not correctly replaced in log messages when using slf4j.
This regression was introduced by afe0767e9c.

Modifications:

- Make use of MessageFormatter
- Add unit test.

Result:

Fixes https://github.com/netty/netty/issues/8483.
This commit is contained in:
Norman Maurer 2018-11-27 11:44:27 +01:00 committed by GitHub
parent 2278991db7
commit f4e4147df8
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
2 changed files with 90 additions and 23 deletions

View File

@ -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 @@ final class LocationAwareSlf4JLogger extends AbstractInternalLogger {
@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 @@ final class LocationAwareSlf4JLogger extends AbstractInternalLogger {
@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 @@ final class LocationAwareSlf4JLogger extends AbstractInternalLogger {
@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 @@ final class LocationAwareSlf4JLogger extends AbstractInternalLogger {
@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 @@ final class LocationAwareSlf4JLogger extends AbstractInternalLogger {
@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));
}
}

View File

@ -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 class Slf4JLoggerFactoryTest {
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());
}
}