Skip to content

Commit

Permalink
Fixes location information in JDK14LoggerAdapter
Browse files Browse the repository at this point in the history 
The `JDK14LoggerAdapter` class uses the wrong caller boundary for location unaware methods.

This PR:

- Sets the correct caller boundary for classic API method calls (`AbstractLogger`),
- Adds the missing `LoggingEventAware` interface and fixes its implementation. The interface was previously implemented, but not declared.
- Adds a test for qos-ch#425.

The `SubstituteLogger` tests depend on qos-ch#438.

Signed-off-by: Piotr P. Karwasz <[email protected]>
  • Loading branch information
@ppkarwasz
ppkarwasz committed Oct 28, 2024
1 parent 69c333d commit 4dd1486
Show file tree
Hide file tree
Showing 3 changed files with 110 additions and 52 deletions.
110 changes: 63 additions & 47 deletions slf4j-jdk14/src/main/java/org/slf4j/jul/JDK14LoggerAdapter.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,21 +24,22 @@
*/
package org.slf4j.jul;

import java.util.List;
import java.util.logging.Level;
import java.util.logging.LogRecord;

import org.slf4j.Logger;
import org.slf4j.Marker;
import org.slf4j.event.EventConstants;
import org.slf4j.event.KeyValuePair;
import org.slf4j.event.LoggingEvent;
import org.slf4j.helpers.AbstractLogger;
import org.slf4j.helpers.FormattingTuple;
import org.slf4j.helpers.LegacyAbstractLogger;
import org.slf4j.helpers.MessageFormatter;
import org.slf4j.helpers.NormalizedParameters;
import org.slf4j.helpers.SubstituteLogger;
import org.slf4j.spi.DefaultLoggingEventBuilder;
import org.slf4j.spi.LocationAwareLogger;
import org.slf4j.spi.LoggingEventAware;

/**
* A wrapper over {@link java.util.logging.Logger java.util.logging.Logger} in
Expand All @@ -49,7 +50,7 @@
* @author Ceki G&uuml;lc&uuml;
* @author Peter Royal
*/
public final class JDK14LoggerAdapter extends LegacyAbstractLogger implements LocationAwareLogger {
public final class JDK14LoggerAdapter extends LegacyAbstractLogger implements LocationAwareLogger, LoggingEventAware {

private static final long serialVersionUID = -8053026990503422791L;

Expand Down Expand Up @@ -139,7 +140,8 @@ public boolean isErrorEnabled() {
*/
@Override
protected void handleNormalizedLoggingCall(org.slf4j.event.Level level, Marker marker, String msg, Object[] args, Throwable throwable) {
innerNormalizedLoggingCallHandler(getFullyQualifiedCallerName(), level, marker, msg, args, throwable);
// AbstractLogger is the entry point of all classic API calls
innerNormalizedLoggingCallHandler(SUPER_OF_SUPER, level, marker, msg, args, throwable);
}

private void innerNormalizedLoggingCallHandler(String fqcn, org.slf4j.event.Level level, Marker marker, String msg, Object[] args, Throwable throwable) {
Expand Down Expand Up @@ -180,13 +182,28 @@ public void log(Marker marker, String callerFQCN, int slf4jLevelInt, String mess
*
* @param record The record to update
*/
final private void fillCallerData(String callerFQCN, LogRecord record) {
private void fillCallerData(String callerFQCN, LogRecord record) {
StackTraceElement[] steArray = new Throwable().getStackTrace();
// Find the first stack trace element matching the caller boundary
int selfIndex = NOT_FOUND;
for (int i = 0; i < steArray.length; i++) {
final String className = steArray[i].getClassName();
if (className.equals(callerFQCN)) {
selfIndex = i;
break;
}
}
// Find the first stack trace element after the caller boundary
int found = NOT_FOUND;
for (int i = selfIndex + 1; i < steArray.length; i++) {
final String className = steArray[i].getClassName();
if (!(className.equals(callerFQCN))) {
found = i;
break;
}
}

int furthestIndex = findFurthestIndex(callerFQCN, steArray);

if (furthestIndex != NOT_FOUND) {
int found = furthestIndex+1;
if (found != NOT_FOUND) {
StackTraceElement ste = steArray[found];
// setting the class name has the side effect of setting
// the needToInferCaller variable to false.
Expand All @@ -195,42 +212,9 @@ final private void fillCallerData(String callerFQCN, LogRecord record) {
}
}

// find the furthest index which matches any of the barrier classes
// We assume that the actual caller is at most MAX_SEARCH_DEPTH calls away
private int findFurthestIndex(String callerFQCN, StackTraceElement[] steArray) {

final int maxIndex = Math.min(MAX_SEARCH_DEPTH, steArray.length);
int furthestIndex = NOT_FOUND;

for (int i = 0; i < maxIndex; i++) {
final String className = steArray[i].getClassName();
if (barrierMatch(callerFQCN, className)) {
furthestIndex = i;
}
}
return furthestIndex;
}

static final int MAX_SEARCH_DEPTH = 12;
static String SELF = JDK14LoggerAdapter.class.getName();
static String SELF = JDK14LoggerAdapter.class.getName();

static String SUPER = LegacyAbstractLogger.class.getName();
static String SUPER_OF_SUPER = AbstractLogger.class.getName();
static String SUBSTITUE = SubstituteLogger.class.getName();
static String FLUENT = DefaultLoggingEventBuilder.class.getName();

static String[] BARRIER_CLASSES = new String[] { SUPER_OF_SUPER, SUPER, SELF, SUBSTITUE, FLUENT };

private boolean barrierMatch(String callerFQCN, String candidateClassName) {
if (candidateClassName.equals(callerFQCN))
return true;
for (String barrierClassName : BARRIER_CLASSES) {
if (barrierClassName.equals(candidateClassName)) {
return true;
}
}
return false;
}

private static Level slf4jLevelIntToJULLevel(int levelInt) {
org.slf4j.event.Level slf4jLevel = org.slf4j.event.Level.intToLevel(levelInt);
Expand Down Expand Up @@ -264,12 +248,15 @@ private static Level slf4jLevelToJULLevel(org.slf4j.event.Level slf4jLevel) {
/**
* @since 1.7.15
*/
@Override
public void log(LoggingEvent event) {
// assumes that the invocation is made from a substitute logger
// this assumption might change in the future with the advent of a fluent API
Level julLevel = slf4jLevelToJULLevel(event.getLevel());
if (logger.isLoggable(julLevel)) {
LogRecord record = eventToRecord(event, julLevel);
String callerBoundary = event.getCallerBoundary();
fillCallerData(callerBoundary != null ? callerBoundary : SELF, record);
logger.log(record);
}
}
Expand All @@ -279,16 +266,18 @@ private LogRecord eventToRecord(LoggingEvent event, Level julLevel) {
Object[] arguments = event.getArgumentArray();
FormattingTuple ft = MessageFormatter.arrayFormat(format, arguments);
if (ft.getThrowable() != null && event.getThrowable() != null) {
throw new IllegalArgumentException("both last element in argument array and last argument are of type Throwable");
throw new IllegalArgumentException(
"both last element in argument array and last argument are of type Throwable");
}

Throwable t = event.getThrowable();
if (ft.getThrowable() != null) {
if (t == null && ft.getThrowable() != null) {
t = ft.getThrowable();
throw new IllegalStateException("fix above code");
}

LogRecord record = new LogRecord(julLevel, ft.getMessage());
LogRecord record = new LogRecord(
julLevel,
prependMarkersAndKeyValuePairs(event.getMarkers(), event.getKeyValuePairs(), ft.getMessage()));
record.setLoggerName(event.getLoggerName());
record.setMillis(event.getTimeStamp());
record.setSourceClassName(EventConstants.NA_SUBST);
Expand All @@ -298,4 +287,31 @@ private LogRecord eventToRecord(LoggingEvent event, Level julLevel) {
return record;
}

private String prependMarkersAndKeyValuePairs(
List<Marker> markers, List<KeyValuePair> KeyValuePairs, String message) {
boolean hasMarkers = isNotEmpty(markers);
boolean hasKeyValuePairs = isNotEmpty(KeyValuePairs);
if (!hasMarkers && !hasKeyValuePairs) {
return message;
}
StringBuilder sb = new StringBuilder(message.length());
if (hasMarkers) {
for (Marker marker : markers) {
sb.append(marker).append(' ');
}
}
if (hasKeyValuePairs) {
for (KeyValuePair keyValuePair : KeyValuePairs) {
sb.append(keyValuePair.key)
.append('=')
.append(keyValuePair.value)
.append(' ');
}
}
return sb.append(message).toString();
}

private boolean isNotEmpty(List<?> list) {
return list != null && !list.isEmpty();
}
}
41 changes: 36 additions & 5 deletions slf4j-jdk14/src/test/java/org/slf4j/issue/CallerInfoTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,6 @@
import java.util.List;
import java.util.concurrent.LinkedBlockingQueue;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.LogRecord;

import org.junit.After;
Expand All @@ -15,23 +14,25 @@
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.event.EventConstants;
import org.slf4j.event.Level;
import org.slf4j.event.SubstituteLoggingEvent;
import org.slf4j.helpers.SubstituteLogger;
import org.slf4j.helpers.SubstituteServiceProvider;
import org.slf4j.jul.ListHandler;
import org.slf4j.spi.CallerBoundaryAware;
import org.slf4j.spi.LocationAwareLogger;
import org.slf4j.spi.LoggingEventBuilder;

public class CallerInfoTest {
Level oldLevel;
java.util.logging.Level oldLevel;
java.util.logging.Logger root = java.util.logging.Logger.getLogger("");

ListHandler listHandler = new ListHandler();

@Before
public void setUp() throws Exception {
oldLevel = root.getLevel();
root.setLevel(Level.FINE);
root.setLevel(java.util.logging.Level.FINE);
// removeAllHandlers(root);
root.addHandler(listHandler);
}
Expand Down Expand Up @@ -63,6 +64,27 @@ public void testCallerInfo() {
assertEquals(this.getClass().getName(), logRecod.getSourceClassName());
}

/**
* Tests a wrapper that uses the {@link LocationAwareLogger} API.
*
* @see <a href="https://github.com/qos-ch/slf4j/issues/425">#425</a>
*/
@Test
public void testCallerInfoWithAWrapper() {
Logger logger = LoggerFactory.getLogger("bla");
LoggingWrapper wrappedLogger = new LoggingWrapper(logger);

wrappedLogger.logWithLocationAwareApi("hello");

List<LogRecord> recordList = listHandler.recordList;

assertEquals(1, recordList.size());

LogRecord logRecord = recordList.get(0);
assertEquals(this.getClass().getName(), logRecord.getSourceClassName());
assertEquals("testCallerInfoWithAWrapper", logRecord.getSourceMethodName());
}

// Do we preserve location info using fluent API?
// See https://jira.qos.ch/browse/SLF4J-511

Expand All @@ -79,6 +101,9 @@ public void testCallerInfoWithFluentAPI() {
assertEquals(this.getClass().getName(), logRecod.getSourceClassName());
}

/**
* Tests a wrapper that uses the Fluent API.
*/
@Test
public void testCallerInfoWithFluentAPIAndAWrapper() {
Logger logger = LoggerFactory.getLogger("bla");
Expand Down Expand Up @@ -144,15 +169,21 @@ static class LoggingWrapper {
LoggingWrapper(Logger aLogger) {
this.underlyingLogger = aLogger;
}

public void logWithEvent(String msg) {
LoggingEventBuilder lev = underlyingLogger.atInfo();
// setting the caller boundary to LoggingWrapper
if(lev instanceof CallerBoundaryAware) {
if (lev instanceof CallerBoundaryAware) {
// builder is CallerBoundaryAware
((CallerBoundaryAware) lev).setCallerBoundary(LoggingWrapper.class.getName());
}
lev.log(msg);
}
}

public void logWithLocationAwareApi(String msg) {
assertTrue("Logger is an instance of LocationAwareLogger", underlyingLogger instanceof LocationAwareLogger);
((LocationAwareLogger) underlyingLogger)
.log(null, LoggingWrapper.class.getName(), Level.INFO.toInt(), msg, null, null);
}
}
}
11 changes: 11 additions & 0 deletions slf4j-jdk14/src/test/java/org/slf4j/jul/FluentApiInvocationTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@
import org.junit.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MarkerFactory;

public class FluentApiInvocationTest {

Expand Down Expand Up @@ -130,6 +131,16 @@ public void messageWithKeyValuePair() {

}

@Test
public void messageWithMarkers() {
String msg = "Hello world.";
logger.atDebug()
.addMarker(MarkerFactory.getMarker("A"))
.addMarker(MarkerFactory.getMarker("B"))
.log(msg);
assertLogMessage("A B Hello world.", 0);
}

private void assertLogMessage(String expected, int index) {
LogRecord logRecord = listHandler.recordList.get(index);
Assert.assertNotNull(logRecord);
Expand Down

0 comments on commit 4dd1486

Please sign in to comment.