Skip to content

Commit 4dd1486

Browse files
ppkarwaszppkarwasz
committed
Fixes location information in JDK14LoggerAdapter
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 #425. The `SubstituteLogger` tests depend on #438. Signed-off-by: Piotr P. Karwasz <[email protected]>
1 parent 69c333d commit 4dd1486

File tree

3 files changed

+110
-52
lines changed

3 files changed

+110
-52
lines changed

‎slf4j-jdk14/src/main/java/org/slf4j/jul/JDK14LoggerAdapter.java‎

Lines changed: 63 additions & 47 deletions
Original file line numberDiff line numberDiff line change
@@ -24,21 +24,22 @@
2424
*/
2525
package org.slf4j.jul;
2626

27+
import java.util.List;
2728
import java.util.logging.Level;
2829
import java.util.logging.LogRecord;
2930

3031
import org.slf4j.Logger;
3132
import org.slf4j.Marker;
3233
import org.slf4j.event.EventConstants;
34+
import org.slf4j.event.KeyValuePair;
3335
import org.slf4j.event.LoggingEvent;
3436
import org.slf4j.helpers.AbstractLogger;
3537
import org.slf4j.helpers.FormattingTuple;
3638
import org.slf4j.helpers.LegacyAbstractLogger;
3739
import org.slf4j.helpers.MessageFormatter;
3840
import org.slf4j.helpers.NormalizedParameters;
39-
import org.slf4j.helpers.SubstituteLogger;
40-
import org.slf4j.spi.DefaultLoggingEventBuilder;
4141
import org.slf4j.spi.LocationAwareLogger;
42+
import org.slf4j.spi.LoggingEventAware;
4243

4344
/**
4445
* A wrapper over {@link java.util.logging.Logger java.util.logging.Logger} in
@@ -49,7 +50,7 @@
4950
* @author Ceki G&uuml;lc&uuml;
5051
* @author Peter Royal
5152
*/
52-
public final class JDK14LoggerAdapter extends LegacyAbstractLogger implements LocationAwareLogger {
53+
public final class JDK14LoggerAdapter extends LegacyAbstractLogger implements LocationAwareLogger, LoggingEventAware {
5354

5455
private static final long serialVersionUID = -8053026990503422791L;
5556

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

145147
private void innerNormalizedLoggingCallHandler(String fqcn, org.slf4j.event.Level level, Marker marker, String msg, Object[] args, Throwable throwable) {
@@ -180,13 +182,28 @@ public void log(Marker marker, String callerFQCN, int slf4jLevelInt, String mess
180182
*
181183
* @param record The record to update
182184
*/
183-
final private void fillCallerData(String callerFQCN, LogRecord record) {
185+
private void fillCallerData(String callerFQCN, LogRecord record) {
184186
StackTraceElement[] steArray = new Throwable().getStackTrace();
187+
// Find the first stack trace element matching the caller boundary
188+
int selfIndex = NOT_FOUND;
189+
for (int i = 0; i < steArray.length; i++) {
190+
final String className = steArray[i].getClassName();
191+
if (className.equals(callerFQCN)) {
192+
selfIndex = i;
193+
break;
194+
}
195+
}
196+
// Find the first stack trace element after the caller boundary
197+
int found = NOT_FOUND;
198+
for (int i = selfIndex + 1; i < steArray.length; i++) {
199+
final String className = steArray[i].getClassName();
200+
if (!(className.equals(callerFQCN))) {
201+
found = i;
202+
break;
203+
}
204+
}
185205

186-
int furthestIndex = findFurthestIndex(callerFQCN, steArray);
187-
188-
if (furthestIndex != NOT_FOUND) {
189-
int found = furthestIndex+1;
206+
if (found != NOT_FOUND) {
190207
StackTraceElement ste = steArray[found];
191208
// setting the class name has the side effect of setting
192209
// the needToInferCaller variable to false.
@@ -195,42 +212,9 @@ final private void fillCallerData(String callerFQCN, LogRecord record) {
195212
}
196213
}
197214

198-
// find the furthest index which matches any of the barrier classes
199-
// We assume that the actual caller is at most MAX_SEARCH_DEPTH calls away
200-
private int findFurthestIndex(String callerFQCN, StackTraceElement[] steArray) {
201-
202-
final int maxIndex = Math.min(MAX_SEARCH_DEPTH, steArray.length);
203-
int furthestIndex = NOT_FOUND;
204-
205-
for (int i = 0; i < maxIndex; i++) {
206-
final String className = steArray[i].getClassName();
207-
if (barrierMatch(callerFQCN, className)) {
208-
furthestIndex = i;
209-
}
210-
}
211-
return furthestIndex;
212-
}
213-
214-
static final int MAX_SEARCH_DEPTH = 12;
215-
static String SELF = JDK14LoggerAdapter.class.getName();
215+
static String SELF = JDK14LoggerAdapter.class.getName();
216216

217-
static String SUPER = LegacyAbstractLogger.class.getName();
218217
static String SUPER_OF_SUPER = AbstractLogger.class.getName();
219-
static String SUBSTITUE = SubstituteLogger.class.getName();
220-
static String FLUENT = DefaultLoggingEventBuilder.class.getName();
221-
222-
static String[] BARRIER_CLASSES = new String[] { SUPER_OF_SUPER, SUPER, SELF, SUBSTITUE, FLUENT };
223-
224-
private boolean barrierMatch(String callerFQCN, String candidateClassName) {
225-
if (candidateClassName.equals(callerFQCN))
226-
return true;
227-
for (String barrierClassName : BARRIER_CLASSES) {
228-
if (barrierClassName.equals(candidateClassName)) {
229-
return true;
230-
}
231-
}
232-
return false;
233-
}
234218

235219
private static Level slf4jLevelIntToJULLevel(int levelInt) {
236220
org.slf4j.event.Level slf4jLevel = org.slf4j.event.Level.intToLevel(levelInt);
@@ -264,12 +248,15 @@ private static Level slf4jLevelToJULLevel(org.slf4j.event.Level slf4jLevel) {
264248
/**
265249
* @since 1.7.15
266250
*/
251+
@Override
267252
public void log(LoggingEvent event) {
268253
// assumes that the invocation is made from a substitute logger
269254
// this assumption might change in the future with the advent of a fluent API
270255
Level julLevel = slf4jLevelToJULLevel(event.getLevel());
271256
if (logger.isLoggable(julLevel)) {
272257
LogRecord record = eventToRecord(event, julLevel);
258+
String callerBoundary = event.getCallerBoundary();
259+
fillCallerData(callerBoundary != null ? callerBoundary : SELF, record);
273260
logger.log(record);
274261
}
275262
}
@@ -279,16 +266,18 @@ private LogRecord eventToRecord(LoggingEvent event, Level julLevel) {
279266
Object[] arguments = event.getArgumentArray();
280267
FormattingTuple ft = MessageFormatter.arrayFormat(format, arguments);
281268
if (ft.getThrowable() != null && event.getThrowable() != null) {
282-
throw new IllegalArgumentException("both last element in argument array and last argument are of type Throwable");
269+
throw new IllegalArgumentException(
270+
"both last element in argument array and last argument are of type Throwable");
283271
}
284272

285273
Throwable t = event.getThrowable();
286-
if (ft.getThrowable() != null) {
274+
if (t == null && ft.getThrowable() != null) {
287275
t = ft.getThrowable();
288-
throw new IllegalStateException("fix above code");
289276
}
290277

291-
LogRecord record = new LogRecord(julLevel, ft.getMessage());
278+
LogRecord record = new LogRecord(
279+
julLevel,
280+
prependMarkersAndKeyValuePairs(event.getMarkers(), event.getKeyValuePairs(), ft.getMessage()));
292281
record.setLoggerName(event.getLoggerName());
293282
record.setMillis(event.getTimeStamp());
294283
record.setSourceClassName(EventConstants.NA_SUBST);
@@ -298,4 +287,31 @@ private LogRecord eventToRecord(LoggingEvent event, Level julLevel) {
298287
return record;
299288
}
300289

290+
private String prependMarkersAndKeyValuePairs(
291+
List<Marker> markers, List<KeyValuePair> KeyValuePairs, String message) {
292+
boolean hasMarkers = isNotEmpty(markers);
293+
boolean hasKeyValuePairs = isNotEmpty(KeyValuePairs);
294+
if (!hasMarkers && !hasKeyValuePairs) {
295+
return message;
296+
}
297+
StringBuilder sb = new StringBuilder(message.length());
298+
if (hasMarkers) {
299+
for (Marker marker : markers) {
300+
sb.append(marker).append(' ');
301+
}
302+
}
303+
if (hasKeyValuePairs) {
304+
for (KeyValuePair keyValuePair : KeyValuePairs) {
305+
sb.append(keyValuePair.key)
306+
.append('=')
307+
.append(keyValuePair.value)
308+
.append(' ');
309+
}
310+
}
311+
return sb.append(message).toString();
312+
}
313+
314+
private boolean isNotEmpty(List<?> list) {
315+
return list != null && !list.isEmpty();
316+
}
301317
}

‎slf4j-jdk14/src/test/java/org/slf4j/issue/CallerInfoTest.java‎

Lines changed: 36 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,6 @@
66
import java.util.List;
77
import java.util.concurrent.LinkedBlockingQueue;
88
import java.util.logging.Handler;
9-
import java.util.logging.Level;
109
import java.util.logging.LogRecord;
1110

1211
import org.junit.After;
@@ -15,23 +14,25 @@
1514
import org.slf4j.Logger;
1615
import org.slf4j.LoggerFactory;
1716
import org.slf4j.event.EventConstants;
17+
import org.slf4j.event.Level;
1818
import org.slf4j.event.SubstituteLoggingEvent;
1919
import org.slf4j.helpers.SubstituteLogger;
2020
import org.slf4j.helpers.SubstituteServiceProvider;
2121
import org.slf4j.jul.ListHandler;
2222
import org.slf4j.spi.CallerBoundaryAware;
23+
import org.slf4j.spi.LocationAwareLogger;
2324
import org.slf4j.spi.LoggingEventBuilder;
2425

2526
public class CallerInfoTest {
26-
Level oldLevel;
27+
java.util.logging.Level oldLevel;
2728
java.util.logging.Logger root = java.util.logging.Logger.getLogger("");
2829

2930
ListHandler listHandler = new ListHandler();
3031

3132
@Before
3233
public void setUp() throws Exception {
3334
oldLevel = root.getLevel();
34-
root.setLevel(Level.FINE);
35+
root.setLevel(java.util.logging.Level.FINE);
3536
// removeAllHandlers(root);
3637
root.addHandler(listHandler);
3738
}
@@ -63,6 +64,27 @@ public void testCallerInfo() {
6364
assertEquals(this.getClass().getName(), logRecod.getSourceClassName());
6465
}
6566

67+
/**
68+
* Tests a wrapper that uses the {@link LocationAwareLogger} API.
69+
*
70+
* @see <a href="https://github.com/qos-ch/slf4j/issues/425">#425</a>
71+
*/
72+
@Test
73+
public void testCallerInfoWithAWrapper() {
74+
Logger logger = LoggerFactory.getLogger("bla");
75+
LoggingWrapper wrappedLogger = new LoggingWrapper(logger);
76+
77+
wrappedLogger.logWithLocationAwareApi("hello");
78+
79+
List<LogRecord> recordList = listHandler.recordList;
80+
81+
assertEquals(1, recordList.size());
82+
83+
LogRecord logRecord = recordList.get(0);
84+
assertEquals(this.getClass().getName(), logRecord.getSourceClassName());
85+
assertEquals("testCallerInfoWithAWrapper", logRecord.getSourceMethodName());
86+
}
87+
6688
// Do we preserve location info using fluent API?
6789
// See https://jira.qos.ch/browse/SLF4J-511
6890

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

104+
/**
105+
* Tests a wrapper that uses the Fluent API.
106+
*/
82107
@Test
83108
public void testCallerInfoWithFluentAPIAndAWrapper() {
84109
Logger logger = LoggerFactory.getLogger("bla");
@@ -144,15 +169,21 @@ static class LoggingWrapper {
144169
LoggingWrapper(Logger aLogger) {
145170
this.underlyingLogger = aLogger;
146171
}
172+
147173
public void logWithEvent(String msg) {
148174
LoggingEventBuilder lev = underlyingLogger.atInfo();
149175
// setting the caller boundary to LoggingWrapper
150-
if(lev instanceof CallerBoundaryAware) {
176+
if (lev instanceof CallerBoundaryAware) {
151177
// builder is CallerBoundaryAware
152178
((CallerBoundaryAware) lev).setCallerBoundary(LoggingWrapper.class.getName());
153179
}
154180
lev.log(msg);
155181
}
156-
}
157182

183+
public void logWithLocationAwareApi(String msg) {
184+
assertTrue("Logger is an instance of LocationAwareLogger", underlyingLogger instanceof LocationAwareLogger);
185+
((LocationAwareLogger) underlyingLogger)
186+
.log(null, LoggingWrapper.class.getName(), Level.INFO.toInt(), msg, null, null);
187+
}
188+
}
158189
}

‎slf4j-jdk14/src/test/java/org/slf4j/jul/FluentApiInvocationTest.java‎

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@
1313
import org.junit.Test;
1414
import org.slf4j.Logger;
1515
import org.slf4j.LoggerFactory;
16+
import org.slf4j.MarkerFactory;
1617

1718
public class FluentApiInvocationTest {
1819

@@ -130,6 +131,16 @@ public void messageWithKeyValuePair() {
130131

131132
}
132133

134+
@Test
135+
public void messageWithMarkers() {
136+
String msg = "Hello world.";
137+
logger.atDebug()
138+
.addMarker(MarkerFactory.getMarker("A"))
139+
.addMarker(MarkerFactory.getMarker("B"))
140+
.log(msg);
141+
assertLogMessage("A B Hello world.", 0);
142+
}
143+
133144
private void assertLogMessage(String expected, int index) {
134145
LogRecord logRecord = listHandler.recordList.get(index);
135146
Assert.assertNotNull(logRecord);

0 commit comments

Comments
 (0)