Core: Fix location information for loggers

This change corrects the location information gathered by the loggers so that when printing class name, method name, and line numbers in the log pattern, the information from the class calling the logger is used rather than a location within the logger itself.

Closes #5130
This commit is contained in:
Satoyuki Tsukano 2014-02-09 22:55:20 +09:00 committed by Colin Goodheart-Smithe
parent 35f55608cc
commit 4ebbb657d8
8 changed files with 488 additions and 37 deletions

View File

@ -0,0 +1,106 @@
/*
* Licensed to Elasticsearch under one or more contributor
* license agreements. See the NOTICE file distributed with
* this work for additional information regarding copyright
* ownership. Elasticsearch licenses this file to you under
* the Apache License, Version 2.0 (the "License"); you may
* not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing,
* software distributed under the License is distributed on an
* "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
* KIND, either express or implied. See the License for the
* specific language governing permissions and limitations
* under the License.
*/
package org.elasticsearch.common.logging.jdk;
import org.elasticsearch.common.logging.support.AbstractESLogger;
import java.util.logging.Level;
import java.util.logging.LogRecord;
/**
* A {@link LogRecord} which is used in conjunction with {@link JdkESLogger}
* with the ability to provide the class name, method name and line number
* information of the code calling the logger
*/
public class ESLogRecord extends LogRecord {
private static final long serialVersionUID = 1107741560233585726L;
private static final String FQCN = AbstractESLogger.class.getName();
private String sourceClassName;
private String sourceMethodName;
private transient boolean needToInferCaller;
public ESLogRecord(Level level, String msg) {
super(level, msg);
needToInferCaller = true;
}
public String getSourceClassName() {
if (needToInferCaller) {
inferCaller();
}
return sourceClassName;
}
public void setSourceClassName(String sourceClassName) {
this.sourceClassName = sourceClassName;
needToInferCaller = false;
}
public String getSourceMethodName() {
if (needToInferCaller) {
inferCaller();
}
return sourceMethodName;
}
public void setSourceMethodName(String sourceMethodName) {
this.sourceMethodName = sourceMethodName;
needToInferCaller = false;
}
/**
* Determines the source information for the caller of the logger (class
* name, method name, and line number)
*/
private void inferCaller() {
needToInferCaller = false;
Throwable throwable = new Throwable();
boolean lookingForLogger = true;
for (final StackTraceElement frame : throwable.getStackTrace()) {
String cname = frame.getClassName();
boolean isLoggerImpl = isLoggerImplFrame(cname);
if (lookingForLogger) {
// Skip all frames until we have found the first logger frame.
if (isLoggerImpl) {
lookingForLogger = false;
}
} else {
if (!isLoggerImpl) {
// skip reflection call
if (!cname.startsWith("java.lang.reflect.") && !cname.startsWith("sun.reflect.")) {
// We've found the relevant frame.
setSourceClassName(cname);
setSourceMethodName(frame.getMethodName());
return;
}
}
}
}
// We haven't found a suitable frame, so just punt. This is
// OK as we are only committed to making a "best effort" here.
}
private boolean isLoggerImplFrame(String cname) {
// the log record could be created for a platform logger
return cname.equals(FQCN);
}
}

View File

@ -22,6 +22,7 @@ package org.elasticsearch.common.logging.jdk;
import org.elasticsearch.common.logging.support.AbstractESLogger;
import java.util.logging.Level;
import java.util.logging.LogRecord;
import java.util.logging.Logger;
/**
@ -31,12 +32,9 @@ public class JdkESLogger extends AbstractESLogger {
private final Logger logger;
private final String name;
public JdkESLogger(String prefix, String name, Logger logger) {
public JdkESLogger(String prefix, Logger logger) {
super(prefix);
this.logger = logger;
this.name = name;
}
@Override
@ -96,51 +94,70 @@ public class JdkESLogger extends AbstractESLogger {
@Override
protected void internalTrace(String msg) {
logger.logp(Level.FINEST, name, null, msg);
LogRecord record = new ESLogRecord(Level.FINEST, msg);
logger.log(record);
}
@Override
protected void internalTrace(String msg, Throwable cause) {
logger.logp(Level.FINEST, name, null, msg, cause);
LogRecord record = new ESLogRecord(Level.FINEST, msg);
record.setThrown(cause);
logger.log(record);
}
@Override
protected void internalDebug(String msg) {
logger.logp(Level.FINE, name, null, msg);
LogRecord record = new ESLogRecord(Level.FINE, msg);
logger.log(record);
}
@Override
protected void internalDebug(String msg, Throwable cause) {
logger.logp(Level.FINE, name, null, msg, cause);
LogRecord record = new ESLogRecord(Level.FINE, msg);
record.setThrown(cause);
logger.log(record);
}
@Override
protected void internalInfo(String msg) {
logger.logp(Level.INFO, name, null, msg);
LogRecord record = new ESLogRecord(Level.INFO, msg);
logger.log(record);
}
@Override
protected void internalInfo(String msg, Throwable cause) {
logger.logp(Level.INFO, name, null, msg, cause);
LogRecord record = new ESLogRecord(Level.INFO, msg);
record.setThrown(cause);
logger.log(record);
}
@Override
protected void internalWarn(String msg) {
logger.logp(Level.WARNING, name, null, msg);
LogRecord record = new ESLogRecord(Level.WARNING, msg);
logger.log(record);
}
@Override
protected void internalWarn(String msg, Throwable cause) {
logger.logp(Level.WARNING, name, null, msg, cause);
LogRecord record = new ESLogRecord(Level.WARNING, msg);
record.setThrown(cause);
logger.log(record);
}
@Override
protected void internalError(String msg) {
logger.logp(Level.SEVERE, name, null, msg);
LogRecord record = new ESLogRecord(Level.SEVERE, msg);
logger.log(record);
}
@Override
protected void internalError(String msg, Throwable cause) {
logger.logp(Level.SEVERE, name, null, msg, cause);
LogRecord record = new ESLogRecord(Level.SEVERE, msg);
record.setThrown(cause);
logger.log(record);
}
protected Logger logger() {
return logger;
}
}

View File

@ -22,8 +22,6 @@ package org.elasticsearch.common.logging.jdk;
import org.elasticsearch.common.logging.ESLogger;
import org.elasticsearch.common.logging.ESLoggerFactory;
import java.util.logging.LogManager;
/**
*
*/
@ -37,6 +35,6 @@ public class JdkESLoggerFactory extends ESLoggerFactory {
@Override
protected ESLogger newInstance(String prefix, String name) {
final java.util.logging.Logger logger = java.util.logging.Logger.getLogger(name);
return new JdkESLogger(prefix, name, logger);
return new JdkESLogger(prefix, logger);
}
}

View File

@ -29,6 +29,7 @@ import org.elasticsearch.common.logging.support.AbstractESLogger;
public class Log4jESLogger extends AbstractESLogger {
private final org.apache.log4j.Logger logger;
private final String FQCN = AbstractESLogger.class.getName();
public Log4jESLogger(String prefix, Logger logger) {
super(prefix);
@ -95,51 +96,51 @@ public class Log4jESLogger extends AbstractESLogger {
@Override
protected void internalTrace(String msg) {
logger.trace(msg);
logger.log(FQCN, Level.TRACE, msg, null);
}
@Override
protected void internalTrace(String msg, Throwable cause) {
logger.trace(msg, cause);
logger.log(FQCN, Level.TRACE, msg, cause);
}
@Override
protected void internalDebug(String msg) {
logger.debug(msg);
logger.log(FQCN, Level.DEBUG, msg, null);
}
@Override
protected void internalDebug(String msg, Throwable cause) {
logger.debug(msg, cause);
logger.log(FQCN, Level.DEBUG, msg, cause);
}
@Override
protected void internalInfo(String msg) {
logger.info(msg);
logger.log(FQCN, Level.INFO, msg, null);
}
@Override
protected void internalInfo(String msg, Throwable cause) {
logger.info(msg, cause);
logger.log(FQCN, Level.INFO, msg, cause);
}
@Override
protected void internalWarn(String msg) {
logger.warn(msg);
logger.log(FQCN, Level.WARN, msg, null);
}
@Override
protected void internalWarn(String msg, Throwable cause) {
logger.warn(msg, cause);
logger.log(FQCN, Level.WARN, msg, cause);
}
@Override
protected void internalError(String msg) {
logger.error(msg);
logger.log(FQCN, Level.ERROR, msg, null);
}
@Override
protected void internalError(String msg, Throwable cause) {
logger.error(msg, cause);
logger.log(FQCN, Level.ERROR, msg, cause);
}
}

View File

@ -21,6 +21,7 @@ package org.elasticsearch.common.logging.slf4j;
import org.elasticsearch.common.logging.support.AbstractESLogger;
import org.slf4j.Logger;
import org.slf4j.spi.LocationAwareLogger;
/**
*
@ -28,10 +29,17 @@ import org.slf4j.Logger;
public class Slf4jESLogger extends AbstractESLogger {
private final Logger logger;
private final LocationAwareLogger lALogger;
private final String FQCN = AbstractESLogger.class.getName();
public Slf4jESLogger(String prefix, Logger logger) {
super(prefix);
this.logger = logger;
if (logger instanceof LocationAwareLogger) {
lALogger = (LocationAwareLogger) logger;
} else {
lALogger = null;
}
}
@Override
@ -77,51 +85,95 @@ public class Slf4jESLogger extends AbstractESLogger {
@Override
protected void internalTrace(String msg) {
logger.trace(msg);
if (lALogger != null) {
lALogger.log(null, FQCN, LocationAwareLogger.TRACE_INT, msg, null, null);
} else {
logger.trace(msg);
}
}
@Override
protected void internalTrace(String msg, Throwable cause) {
logger.trace(msg, cause);
if (lALogger != null) {
lALogger.log(null, FQCN, LocationAwareLogger.TRACE_INT, msg, null, cause);
} else {
logger.trace(msg);
}
}
@Override
protected void internalDebug(String msg) {
logger.debug(msg);
if (lALogger != null) {
lALogger.log(null, FQCN, LocationAwareLogger.DEBUG_INT, msg, null, null);
} else {
logger.debug(msg);
}
}
@Override
protected void internalDebug(String msg, Throwable cause) {
logger.debug(msg, cause);
if (lALogger != null) {
lALogger.log(null, FQCN, LocationAwareLogger.DEBUG_INT, msg, null, cause);
} else {
logger.debug(msg);
}
}
@Override
protected void internalInfo(String msg) {
logger.info(msg);
if (lALogger != null) {
lALogger.log(null, FQCN, LocationAwareLogger.INFO_INT, msg, null, null);
} else {
logger.info(msg);
}
}
@Override
protected void internalInfo(String msg, Throwable cause) {
logger.info(msg, cause);
if (lALogger != null) {
lALogger.log(null, FQCN, LocationAwareLogger.INFO_INT, msg, null, cause);
} else {
logger.info(msg, cause);
}
}
@Override
protected void internalWarn(String msg) {
logger.warn(msg);
if (lALogger != null) {
lALogger.log(null, FQCN, LocationAwareLogger.WARN_INT, msg, null, null);
} else {
logger.warn(msg);
}
}
@Override
protected void internalWarn(String msg, Throwable cause) {
logger.warn(msg, cause);
if (lALogger != null) {
lALogger.log(null, FQCN, LocationAwareLogger.WARN_INT, msg, null, cause);
} else {
logger.warn(msg);
}
}
@Override
protected void internalError(String msg) {
logger.error(msg);
if (lALogger != null) {
lALogger.log(null, FQCN, LocationAwareLogger.ERROR_INT, msg, null, null);
} else {
logger.error(msg);
}
}
@Override
protected void internalError(String msg, Throwable cause) {
logger.error(msg, cause);
if (lALogger != null) {
lALogger.log(null, FQCN, LocationAwareLogger.ERROR_INT, msg, null, cause);
} else {
logger.error(msg);
}
}
protected Logger logger() {
return logger;
}
}

View File

@ -0,0 +1,120 @@
/*
* Licensed to Elasticsearch under one or more contributor
* license agreements. See the NOTICE file distributed with
* this work for additional information regarding copyright
* ownership. Elasticsearch licenses this file to you under
* the Apache License, Version 2.0 (the "License"); you may
* not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing,
* software distributed under the License is distributed on an
* "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
* KIND, either express or implied. See the License for the
* specific language governing permissions and limitations
* under the License.
*/
package org.elasticsearch.common.logging.jdk;
import org.elasticsearch.common.logging.ESLogger;
import org.elasticsearch.test.ElasticsearchTestCase;
import org.junit.Test;
import java.util.ArrayList;
import java.util.List;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.LogRecord;
import java.util.logging.Logger;
import static org.hamcrest.Matchers.equalTo;
import static org.hamcrest.Matchers.notNullValue;
public class JDKESLoggerTests extends ElasticsearchTestCase {
private ESLogger esTestLogger;
private TestHandler testHandler;
@Override
public void setUp() throws Exception {
super.setUp();
JdkESLoggerFactory esTestLoggerFactory = new JdkESLoggerFactory();
esTestLogger = esTestLoggerFactory.newInstance("test");
Logger testLogger = ((JdkESLogger) esTestLogger).logger();
testLogger.setLevel(Level.FINEST);
assertThat(testLogger.getLevel(), equalTo(Level.FINEST));
testHandler = new TestHandler();
testLogger.addHandler(testHandler);
}
@Test
public void locationInfoTest() {
esTestLogger.error("This is an error");
esTestLogger.warn("This is a warning");
esTestLogger.info("This is an info");
esTestLogger.debug("This is a debug");
esTestLogger.trace("This is a trace");
List<LogRecord> records = testHandler.getEvents();
assertThat(records, notNullValue());
assertThat(records.size(), equalTo(5));
LogRecord record = records.get(0);
assertThat(record, notNullValue());
assertThat(record.getLevel(), equalTo(Level.SEVERE));
assertThat(record.getMessage(), equalTo("This is an error"));
assertThat(record.getSourceClassName(), equalTo(JDKESLoggerTests.class.getCanonicalName()));
assertThat(record.getSourceMethodName(), equalTo("locationInfoTest"));
record = records.get(1);
assertThat(record, notNullValue());
assertThat(record.getLevel(), equalTo(Level.WARNING));
assertThat(record.getMessage(), equalTo("This is a warning"));
assertThat(record.getSourceClassName(), equalTo(JDKESLoggerTests.class.getCanonicalName()));
assertThat(record.getSourceMethodName(), equalTo("locationInfoTest"));
record = records.get(2);
assertThat(record, notNullValue());
assertThat(record.getLevel(), equalTo(Level.INFO));
assertThat(record.getMessage(), equalTo("This is an info"));
assertThat(record.getSourceClassName(), equalTo(JDKESLoggerTests.class.getCanonicalName()));
assertThat(record.getSourceMethodName(), equalTo("locationInfoTest"));
record = records.get(3);
assertThat(record, notNullValue());
assertThat(record.getLevel(), equalTo(Level.FINE));
assertThat(record.getMessage(), equalTo("This is a debug"));
assertThat(record.getSourceClassName(), equalTo(JDKESLoggerTests.class.getCanonicalName()));
assertThat(record.getSourceMethodName(), equalTo("locationInfoTest"));
record = records.get(4);
assertThat(record, notNullValue());
assertThat(record.getLevel(), equalTo(Level.FINEST));
assertThat(record.getMessage(), equalTo("This is a trace"));
assertThat(record.getSourceClassName(), equalTo(JDKESLoggerTests.class.getCanonicalName()));
assertThat(record.getSourceMethodName(), equalTo("locationInfoTest"));
}
private static class TestHandler extends Handler {
private List<LogRecord> records = new ArrayList<>();
@Override
public void close() {
}
public List<LogRecord> getEvents() {
return records;
}
@Override
public void publish(LogRecord record) {
// Forces it to generate the location information
record.getSourceClassName();
records.add(record);
}
@Override
public void flush() {
}
}
}

View File

@ -0,0 +1,145 @@
/*
* Licensed to Elasticsearch under one or more contributor
* license agreements. See the NOTICE file distributed with
* this work for additional information regarding copyright
* ownership. Elasticsearch licenses this file to you under
* the Apache License, Version 2.0 (the "License"); you may
* not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing,
* software distributed under the License is distributed on an
* "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
* KIND, either express or implied. See the License for the
* specific language governing permissions and limitations
* under the License.
*/
package org.elasticsearch.common.logging.log4j;
import org.apache.log4j.AppenderSkeleton;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.apache.log4j.spi.LocationInfo;
import org.apache.log4j.spi.LoggingEvent;
import org.elasticsearch.common.logging.ESLogger;
import org.elasticsearch.common.settings.ImmutableSettings;
import org.elasticsearch.common.settings.Settings;
import org.elasticsearch.test.ElasticsearchTestCase;
import org.junit.Test;
import java.io.File;
import java.net.URL;
import java.util.ArrayList;
import java.util.List;
import static org.hamcrest.Matchers.equalTo;
import static org.hamcrest.Matchers.notNullValue;
public class Log4jESLoggerTests extends ElasticsearchTestCase {
private ESLogger esTestLogger;
private TestAppender testAppender;
@Override
public void setUp() throws Exception {
super.setUp();
File configDir = resolveConfigDir();
// Need to set custom path.conf so we can use a custom logging.yml file for the test
Settings settings = ImmutableSettings.builder()
.put("path.conf", configDir.getAbsolutePath())
.build();
LogConfigurator.configure(settings);
esTestLogger = Log4jESLoggerFactory.getLogger("test");
Logger testLogger = ((Log4jESLogger) esTestLogger).logger();
assertThat(testLogger.getLevel(), equalTo(Level.TRACE));
testAppender = new TestAppender();
testLogger.addAppender(testAppender);
}
@Test
public void locationInfoTest() {
esTestLogger.error("This is an error");
esTestLogger.warn("This is a warning");
esTestLogger.info("This is an info");
esTestLogger.debug("This is a debug");
esTestLogger.trace("This is a trace");
List<LoggingEvent> events = testAppender.getEvents();
assertThat(events, notNullValue());
assertThat(events.size(), equalTo(5));
LoggingEvent event = events.get(0);
assertThat(event, notNullValue());
assertThat(event.getLevel(), equalTo(Level.ERROR));
assertThat(event.getRenderedMessage(), equalTo("This is an error"));
LocationInfo locationInfo = event.getLocationInformation();
assertThat(locationInfo, notNullValue());
assertThat(locationInfo.getClassName(), equalTo(Log4jESLoggerTests.class.getCanonicalName()));
assertThat(locationInfo.getMethodName(), equalTo("locationInfoTest"));
event = events.get(1);
assertThat(event, notNullValue());
assertThat(event.getLevel(), equalTo(Level.WARN));
assertThat(event.getRenderedMessage(), equalTo("This is a warning"));
locationInfo = event.getLocationInformation();
assertThat(locationInfo, notNullValue());
assertThat(locationInfo.getClassName(), equalTo(Log4jESLoggerTests.class.getCanonicalName()));
assertThat(locationInfo.getMethodName(), equalTo("locationInfoTest"));
event = events.get(2);
assertThat(event, notNullValue());
assertThat(event.getLevel(), equalTo(Level.INFO));
assertThat(event.getRenderedMessage(), equalTo("This is an info"));
locationInfo = event.getLocationInformation();
assertThat(locationInfo, notNullValue());
assertThat(locationInfo.getClassName(), equalTo(Log4jESLoggerTests.class.getCanonicalName()));
assertThat(locationInfo.getMethodName(), equalTo("locationInfoTest"));
event = events.get(3);
assertThat(event, notNullValue());
assertThat(event.getLevel(), equalTo(Level.DEBUG));
assertThat(event.getRenderedMessage(), equalTo("This is a debug"));
locationInfo = event.getLocationInformation();
assertThat(locationInfo, notNullValue());
assertThat(locationInfo.getClassName(), equalTo(Log4jESLoggerTests.class.getCanonicalName()));
assertThat(locationInfo.getMethodName(), equalTo("locationInfoTest"));
event = events.get(4);
assertThat(event, notNullValue());
assertThat(event.getLevel(), equalTo(Level.TRACE));
assertThat(event.getRenderedMessage(), equalTo("This is a trace"));
locationInfo = event.getLocationInformation();
assertThat(locationInfo, notNullValue());
assertThat(locationInfo.getClassName(), equalTo(Log4jESLoggerTests.class.getCanonicalName()));
assertThat(locationInfo.getMethodName(), equalTo("locationInfoTest"));
}
private static File resolveConfigDir() throws Exception {
URL url = Log4jESLoggerTests.class.getResource("config");
return new File(url.toURI());
}
private static class TestAppender extends AppenderSkeleton {
private List<LoggingEvent> events = new ArrayList<>();
@Override
public void close() {
}
@Override
public boolean requiresLayout() {
return false;
}
@Override
protected void append(LoggingEvent event) {
// Forces it to generate the location information
event.getLocationInformation();
events.add(event);
}
public List<LoggingEvent> getEvents() {
return events;
}
}
}

View File

@ -0,0 +1,12 @@
# you can override this using by setting a system property, for example -Des.logger.level=DEBUG
es.logger.level: INFO
rootLogger: ${es.logger.level}, console
logger:
test: TRACE
appender:
console:
type: console
layout:
type: consolePattern
conversionPattern: "[%d{ISO8601}][%-5p][%-25c] %m%n"