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.

A reset method has also been added to the LogConfigurator class which allows the logging configuration to be reset. This is needed because if the LoggingConfigurationTests and Log4jESLoggerTests are run in the same JVM the second one to run needs to be able to override the log configuration set by the first

Closes #5130, #8052
This commit is contained in:
Satoyuki Tsukano 2014-02-09 22:55:20 +09:00 committed by Colin Goodheart-Smithe
parent 67394aad81
commit e3d5cb903b
10 changed files with 498 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

@ -102,6 +102,14 @@ public class LogConfigurator {
PropertyConfigurator.configure(props);
}
/**
* sets the loaded flag to false so that logging configuration can be
* overridden. Should only be used in tests.
*/
public static void reset() {
loaded = false;
}
public static void resolveConfig(Environment env, final ImmutableSettings.Builder settingsBuilder) {
try {

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

@ -41,6 +41,7 @@ public class LoggingConfigurationTests extends ElasticsearchTestCase {
@Test
public void testMultipleConfigs() throws Exception {
LogConfigurator.reset();
File configDir = resolveConfigDir();
Settings settings = ImmutableSettings.builder()
.put("path.conf", configDir.getAbsolutePath())

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,146 @@
/*
* 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();
LogConfigurator.reset();
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"