Merge pull request #20490 from ywelsch/fix/loggerusagecheck-log4j2

With the switch to Log4j 2 the logger usage checker was temporarily disabled. This adapts the checks to work with Log4j 2 and re-enables the Gradle checks. It also fixes the wrong logger usages that have sneaked into the code base.
This commit is contained in:
Yannick Welsch 2016-09-21 15:42:53 +02:00 committed by GitHub
commit c97e713196
12 changed files with 258 additions and 90 deletions

View File

@ -59,8 +59,7 @@ class PrecommitTasks {
* use the NamingConventionsCheck we break the circular dependency * use the NamingConventionsCheck we break the circular dependency
* here. * here.
*/ */
// https://github.com/elastic/elasticsearch/issues/20243 precommitTasks.add(configureLoggerUsage(project))
// precommitTasks.add(configureLoggerUsage(project))
} }

View File

@ -20,6 +20,8 @@
package org.elasticsearch.common.util; package org.elasticsearch.common.util;
import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.message.ParameterizedMessage;
import org.apache.logging.log4j.util.Supplier;
import org.apache.lucene.util.IOUtils; import org.apache.lucene.util.IOUtils;
import org.elasticsearch.cluster.metadata.IndexMetaData; import org.elasticsearch.cluster.metadata.IndexMetaData;
import org.elasticsearch.common.logging.Loggers; import org.elasticsearch.common.logging.Loggers;
@ -64,8 +66,8 @@ public class IndexFolderUpgrader {
} catch (NoSuchFileException | FileNotFoundException exception) { } catch (NoSuchFileException | FileNotFoundException exception) {
// thrown when the source is non-existent because the folder was renamed // thrown when the source is non-existent because the folder was renamed
// by another node (shared FS) after we checked if the target exists // by another node (shared FS) after we checked if the target exists
logger.error("multiple nodes trying to upgrade [{}] in parallel, retry upgrading with single node", logger.error((Supplier<?>) () -> new ParameterizedMessage("multiple nodes trying to upgrade [{}] in parallel, retry " +
exception, target); "upgrading with single node", target), exception);
throw exception; throw exception;
} finally { } finally {
if (success) { if (success) {

View File

@ -479,7 +479,9 @@ public abstract class Engine implements Closeable {
try { try {
length = directory.fileLength(file); length = directory.fileLength(file);
} catch (NoSuchFileException | FileNotFoundException e) { } catch (NoSuchFileException | FileNotFoundException e) {
logger.warn("Tried to query fileLength but file is gone [{}] [{}]", e, directory, file); final Directory finalDirectory = directory;
logger.warn((Supplier<?>)
() -> new ParameterizedMessage("Tried to query fileLength but file is gone [{}] [{}]", finalDirectory, file), e);
} catch (IOException e) { } catch (IOException e) {
final Directory finalDirectory = directory; final Directory finalDirectory = directory;
logger.warn( logger.warn(

View File

@ -388,7 +388,7 @@ public class Store extends AbstractIndexShardComponent implements Closeable, Ref
} catch (FileNotFoundException | NoSuchFileException ex) { } catch (FileNotFoundException | NoSuchFileException ex) {
logger.info("Failed to open / find files while reading metadata snapshot"); logger.info("Failed to open / find files while reading metadata snapshot");
} catch (ShardLockObtainFailedException ex) { } catch (ShardLockObtainFailedException ex) {
logger.info("{}: failed to obtain shard lock", ex, shardId); logger.info((Supplier<?>) () -> new ParameterizedMessage("{}: failed to obtain shard lock", shardId), ex);
} }
return MetadataSnapshot.EMPTY; return MetadataSnapshot.EMPTY;
} }
@ -420,7 +420,7 @@ public class Store extends AbstractIndexShardComponent implements Closeable, Ref
SegmentInfos segInfo = Lucene.readSegmentInfos(dir); SegmentInfos segInfo = Lucene.readSegmentInfos(dir);
logger.trace("{} loaded segment info [{}]", shardId, segInfo); logger.trace("{} loaded segment info [{}]", shardId, segInfo);
} catch (ShardLockObtainFailedException ex) { } catch (ShardLockObtainFailedException ex) {
logger.error("{} unable to acquire shard lock", ex, shardId); logger.error((Supplier<?>) () -> new ParameterizedMessage("{} unable to acquire shard lock", shardId), ex);
throw new IOException(ex); throw new IOException(ex);
} }
} }

View File

@ -386,7 +386,7 @@ public class IndexingMemoryController extends AbstractComponent implements Index
try { try {
shard.checkIdle(inactiveTimeNS); shard.checkIdle(inactiveTimeNS);
} catch (EngineClosedException e) { } catch (EngineClosedException e) {
logger.trace("ignore exception while checking if shard {} is inactive", e, shard.shardId()); logger.trace((Supplier<?>) () -> new ParameterizedMessage("ignore exception while checking if shard {} is inactive", shard.shardId()), e);
} }
} }
} }

View File

@ -245,7 +245,7 @@ public class PluginsService extends AbstractComponent {
try { try {
reference.onModuleMethod.invoke(plugin.v2(), module); reference.onModuleMethod.invoke(plugin.v2(), module);
} catch (IllegalAccessException | InvocationTargetException e) { } catch (IllegalAccessException | InvocationTargetException e) {
logger.warn("plugin {}, failed to invoke custom onModule method", e, plugin.v1().getName()); logger.warn((Supplier<?>) () -> new ParameterizedMessage("plugin {}, failed to invoke custom onModule method", plugin.v1().getName()), e);
throw new ElasticsearchException("failed to invoke onModule", e); throw new ElasticsearchException("failed to invoke onModule", e);
} catch (Exception e) { } catch (Exception e) {
logger.warn((Supplier<?>) () -> new ParameterizedMessage("plugin {}, failed to invoke custom onModule method", plugin.v1().getName()), e); logger.warn((Supplier<?>) () -> new ParameterizedMessage("plugin {}, failed to invoke custom onModule method", plugin.v1().getName()), e);

View File

@ -395,7 +395,7 @@ public abstract class BlobStoreRepository extends AbstractLifecycleComponent imp
} catch (SnapshotMissingException ex) { } catch (SnapshotMissingException ex) {
throw ex; throw ex;
} catch (IllegalStateException | SnapshotException | ElasticsearchParseException ex) { } catch (IllegalStateException | SnapshotException | ElasticsearchParseException ex) {
logger.warn("cannot read snapshot file [{}]", ex, snapshotId); logger.warn((Supplier<?>) () -> new ParameterizedMessage("cannot read snapshot file [{}]", snapshotId), ex);
} }
MetaData metaData = null; MetaData metaData = null;
try { try {
@ -405,7 +405,7 @@ public abstract class BlobStoreRepository extends AbstractLifecycleComponent imp
metaData = readSnapshotMetaData(snapshotId, null, repositoryData.resolveIndices(indices), true); metaData = readSnapshotMetaData(snapshotId, null, repositoryData.resolveIndices(indices), true);
} }
} catch (IOException | SnapshotException ex) { } catch (IOException | SnapshotException ex) {
logger.warn("cannot read metadata for snapshot [{}]", ex, snapshotId); logger.warn((Supplier<?>) () -> new ParameterizedMessage("cannot read metadata for snapshot [{}]", snapshotId), ex);
} }
try { try {
// Delete snapshot from the index file, since it is the maintainer of truth of active snapshots // Delete snapshot from the index file, since it is the maintainer of truth of active snapshots
@ -601,7 +601,7 @@ public abstract class BlobStoreRepository extends AbstractLifecycleComponent imp
metaDataBuilder.put(indexMetaDataFormat(snapshotVersion).read(indexMetaDataBlobContainer, snapshotId.getUUID()), false); metaDataBuilder.put(indexMetaDataFormat(snapshotVersion).read(indexMetaDataBlobContainer, snapshotId.getUUID()), false);
} catch (ElasticsearchParseException | IOException ex) { } catch (ElasticsearchParseException | IOException ex) {
if (ignoreIndexErrors) { if (ignoreIndexErrors) {
logger.warn("[{}] [{}] failed to read metadata for index", ex, snapshotId, index.getName()); logger.warn((Supplier<?>) () -> new ParameterizedMessage("[{}] [{}] failed to read metadata for index", snapshotId, index.getName()), ex);
} else { } else {
throw ex; throw ex;
} }

View File

@ -529,7 +529,7 @@ public class DiscoveryWithServiceDisruptionsIT extends ESIntegTestCase {
} catch (InterruptedException e) { } catch (InterruptedException e) {
// fine - semaphore interrupt // fine - semaphore interrupt
} catch (AssertionError | Exception e) { } catch (AssertionError | Exception e) {
logger.info("unexpected exception in background thread of [{}]", e, node); logger.info((Supplier<?>) () -> new ParameterizedMessage("unexpected exception in background thread of [{}]", node), e);
} }
} }
}); });

View File

@ -315,7 +315,7 @@ public class GroovyScriptEngineService extends AbstractComponent implements Scri
} }
throw ae; throw ae;
} catch (Exception | NoClassDefFoundError e) { } catch (Exception | NoClassDefFoundError e) {
logger.trace("failed to run {}", e, compiledScript); logger.trace((Supplier<?>) () -> new ParameterizedMessage("failed to run {}", compiledScript), e);
throw new ScriptException("Error evaluating " + compiledScript.name(), e, emptyList(), "", compiledScript.lang()); throw new ScriptException("Error evaluating " + compiledScript.name(), e, emptyList(), "", compiledScript.lang());
} }
} }

View File

@ -21,14 +21,27 @@ import org.elasticsearch.gradle.precommit.PrecommitTasks
dependencies { dependencies {
compile 'org.ow2.asm:asm-debug-all:5.0.4' // use asm-debug-all as asm-all is broken compile 'org.ow2.asm:asm-debug-all:5.0.4' // use asm-debug-all as asm-all is broken
compile "org.apache.logging.log4j:log4j-api:${versions.log4j}"
testCompile "org.elasticsearch.test:framework:${version}" testCompile "org.elasticsearch.test:framework:${version}"
} }
// https://github.com/elastic/elasticsearch/issues/20243 loggerUsageCheck.enabled = false
// loggerUsageCheck.enabled = false
forbiddenApisMain.enabled = true // disabled by parent project forbiddenApisMain.enabled = true // disabled by parent project
forbiddenApisMain { forbiddenApisMain {
signaturesURLs = [PrecommitTasks.getResource('/forbidden/jdk-signatures.txt')] // does not depend on core, only jdk signatures signaturesURLs = [PrecommitTasks.getResource('/forbidden/jdk-signatures.txt')] // does not depend on core, only jdk signatures
} }
jarHell.enabled = true // disabled by parent project jarHell.enabled = true // disabled by parent project
thirdPartyAudit.excludes = [
// log4j
'org.osgi.framework.AdaptPermission',
'org.osgi.framework.AdminPermission',
'org.osgi.framework.Bundle',
'org.osgi.framework.BundleActivator',
'org.osgi.framework.BundleContext',
'org.osgi.framework.BundleEvent',
'org.osgi.framework.SynchronousBundleListener',
'org.osgi.framework.wiring.BundleWire',
'org.osgi.framework.wiring.BundleWiring'
]

View File

@ -19,6 +19,10 @@
package org.elasticsearch.test.loggerusage; package org.elasticsearch.test.loggerusage;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.message.ParameterizedMessage;
import org.apache.logging.log4j.util.Supplier;
import org.objectweb.asm.AnnotationVisitor; import org.objectweb.asm.AnnotationVisitor;
import org.objectweb.asm.ClassReader; import org.objectweb.asm.ClassReader;
import org.objectweb.asm.ClassVisitor; import org.objectweb.asm.ClassVisitor;
@ -52,9 +56,16 @@ import java.util.function.Consumer;
import java.util.function.Predicate; import java.util.function.Predicate;
public class ESLoggerUsageChecker { public class ESLoggerUsageChecker {
public static final String LOGGER_CLASS = "org.elasticsearch.common.logging.ESLogger"; public static final Type LOGGER_CLASS = Type.getType(Logger.class);
public static final String THROWABLE_CLASS = "java.lang.Throwable"; public static final Type THROWABLE_CLASS = Type.getType(Throwable.class);
public static final List<String> LOGGER_METHODS = Arrays.asList("trace", "debug", "info", "warn", "error"); public static final Type STRING_CLASS = Type.getType(String.class);
public static final Type STRING_ARRAY_CLASS = Type.getType(String[].class);
public static final Type PARAMETERIZED_MESSAGE_CLASS = Type.getType(ParameterizedMessage.class);
public static final Type OBJECT_CLASS = Type.getType(Object.class);
public static final Type OBJECT_ARRAY_CLASS = Type.getType(Object[].class);
public static final Type SUPPLIER_ARRAY_CLASS = Type.getType(Supplier[].class);
public static final Type MARKER_CLASS = Type.getType(Marker.class);
public static final List<String> LOGGER_METHODS = Arrays.asList("trace", "debug", "info", "warn", "error", "fatal");
public static final String IGNORE_CHECKS_ANNOTATION = "org.elasticsearch.common.SuppressLoggerChecks"; public static final String IGNORE_CHECKS_ANNOTATION = "org.elasticsearch.common.SuppressLoggerChecks";
@SuppressForbidden(reason = "command line tool") @SuppressForbidden(reason = "command line tool")
@ -143,7 +154,7 @@ public class ESLoggerUsageChecker {
simpleClassName = simpleClassName + ".java"; simpleClassName = simpleClassName + ".java";
StringBuilder sb = new StringBuilder(); StringBuilder sb = new StringBuilder();
sb.append("Bad usage of "); sb.append("Bad usage of ");
sb.append(LOGGER_CLASS).append("#").append(logMethodName); sb.append(LOGGER_CLASS.getClassName()).append("#").append(logMethodName);
sb.append(": "); sb.append(": ");
sb.append(errorMessage); sb.append(errorMessage);
sb.append("\n\tat "); sb.append("\n\tat ");
@ -230,7 +241,7 @@ public class ESLoggerUsageChecker {
} catch (AnalyzerException e) { } catch (AnalyzerException e) {
throw new RuntimeException("Internal error: failed in analysis step", e); throw new RuntimeException("Internal error: failed in analysis step", e);
} }
Frame<BasicValue>[] stringFrames = stringPlaceHolderAnalyzer.getFrames(); Frame<BasicValue>[] logMessageFrames = stringPlaceHolderAnalyzer.getFrames();
Frame<BasicValue>[] arraySizeFrames = arraySizeAnalyzer.getFrames(); Frame<BasicValue>[] arraySizeFrames = arraySizeAnalyzer.getFrames();
AbstractInsnNode[] insns = methodNode.instructions.toArray(); AbstractInsnNode[] insns = methodNode.instructions.toArray();
int lineNumber = -1; int lineNumber = -1;
@ -240,52 +251,140 @@ public class ESLoggerUsageChecker {
LineNumberNode lineNumberNode = (LineNumberNode) insn; LineNumberNode lineNumberNode = (LineNumberNode) insn;
lineNumber = lineNumberNode.line; lineNumber = lineNumberNode.line;
} }
if (insn.getOpcode() == Opcodes.INVOKEVIRTUAL) { if (insn.getOpcode() == Opcodes.INVOKEINTERFACE) {
MethodInsnNode methodInsn = (MethodInsnNode) insn; MethodInsnNode methodInsn = (MethodInsnNode) insn;
if (Type.getObjectType(methodInsn.owner).getClassName().equals(LOGGER_CLASS) == false) { if (Type.getObjectType(methodInsn.owner).equals(LOGGER_CLASS)) {
continue;
}
if (LOGGER_METHODS.contains(methodInsn.name) == false) { if (LOGGER_METHODS.contains(methodInsn.name) == false) {
continue; continue;
} }
BasicValue varArgsSizeObject = getStackValue(arraySizeFrames[i], 0); // last argument
if (varArgsSizeObject instanceof ArraySizeBasicValue == false) {
wrongUsageCallback.accept(new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber,
"Could not determine size of varargs array"));
continue;
}
ArraySizeBasicValue varArgsSize = (ArraySizeBasicValue) varArgsSizeObject;
Type[] argumentTypes = Type.getArgumentTypes(methodInsn.desc); Type[] argumentTypes = Type.getArgumentTypes(methodInsn.desc);
BasicValue logMessageLengthObject = getStackValue(stringFrames[i], argumentTypes.length - 1); // first argument int markerOffset = 0;
if (argumentTypes[0].equals(MARKER_CLASS)) {
markerOffset = 1;
}
int lengthWithoutMarker = argumentTypes.length - markerOffset;
if (lengthWithoutMarker == 2 &&
argumentTypes[markerOffset + 0].equals(STRING_CLASS) &&
(argumentTypes[markerOffset + 1].equals(OBJECT_ARRAY_CLASS) ||
argumentTypes[markerOffset + 1].equals(SUPPLIER_ARRAY_CLASS))) {
// VARARGS METHOD: debug(Marker?, String, (Object...|Supplier...))
checkArrayArgs(methodNode, logMessageFrames[i], arraySizeFrames[i], lineNumber, methodInsn, markerOffset + 0,
markerOffset + 1);
} else if (lengthWithoutMarker >= 2 &&
argumentTypes[markerOffset + 0].equals(STRING_CLASS) &&
argumentTypes[markerOffset + 1].equals(OBJECT_CLASS)) {
// MULTI-PARAM METHOD: debug(Marker?, String, Object p0, ...)
checkFixedArityArgs(methodNode, logMessageFrames[i], lineNumber, methodInsn, markerOffset + 0,
lengthWithoutMarker - 1);
} else if ((lengthWithoutMarker == 1 || lengthWithoutMarker == 2) &&
lengthWithoutMarker == 2 ? argumentTypes[markerOffset + 1].equals(THROWABLE_CLASS) : true) {
// all the rest: debug(Marker?, (Message|MessageSupplier|CharSequence|Object|String|Supplier), Throwable?)
checkFixedArityArgs(methodNode, logMessageFrames[i], lineNumber, methodInsn, markerOffset + 0, 0);
} else {
throw new IllegalStateException("Method invoked on " + LOGGER_CLASS.getClassName() +
" that is not supported by logger usage checker");
}
}
} else if (insn.getOpcode() == Opcodes.INVOKESPECIAL) { // constructor invocation
MethodInsnNode methodInsn = (MethodInsnNode) insn;
if (Type.getObjectType(methodInsn.owner).equals(PARAMETERIZED_MESSAGE_CLASS)) {
Type[] argumentTypes = Type.getArgumentTypes(methodInsn.desc);
if (argumentTypes.length == 2 &&
argumentTypes[0].equals(STRING_CLASS) &&
argumentTypes[1].equals(OBJECT_ARRAY_CLASS)) {
checkArrayArgs(methodNode, logMessageFrames[i], arraySizeFrames[i], lineNumber, methodInsn, 0, 1);
} else if (argumentTypes.length == 2 &&
argumentTypes[0].equals(STRING_CLASS) &&
argumentTypes[1].equals(OBJECT_CLASS)) {
checkFixedArityArgs(methodNode, logMessageFrames[i], lineNumber, methodInsn, 0, 1);
} else if (argumentTypes.length == 3 &&
argumentTypes[0].equals(STRING_CLASS) &&
argumentTypes[1].equals(OBJECT_CLASS) &&
argumentTypes[2].equals(OBJECT_CLASS)) {
checkFixedArityArgs(methodNode, logMessageFrames[i], lineNumber, methodInsn, 0, 2);
} else if (argumentTypes.length == 3 &&
argumentTypes[0].equals(STRING_CLASS) &&
argumentTypes[1].equals(OBJECT_ARRAY_CLASS) &&
argumentTypes[2].equals(THROWABLE_CLASS)) {
checkArrayArgs(methodNode, logMessageFrames[i], arraySizeFrames[i], lineNumber, methodInsn, 0, 1);
} else if (argumentTypes.length == 3 &&
argumentTypes[0].equals(STRING_CLASS) &&
argumentTypes[1].equals(STRING_ARRAY_CLASS) &&
argumentTypes[2].equals(THROWABLE_CLASS)) {
checkArrayArgs(methodNode, logMessageFrames[i], arraySizeFrames[i], lineNumber, methodInsn, 0, 1);
} else {
throw new IllegalStateException("Constructor invoked on " + PARAMETERIZED_MESSAGE_CLASS.getClassName() +
" that is not supported by logger usage checker");
}
}
}
}
}
private void checkFixedArityArgs(MethodNode methodNode, Frame<BasicValue> logMessageFrame, int lineNumber,
MethodInsnNode methodInsn, int messageIndex, int positionalArgsLength) {
PlaceHolderStringBasicValue logMessageLength = checkLogMessageConsistency(methodNode, logMessageFrame, lineNumber, methodInsn,
messageIndex, positionalArgsLength);
if (logMessageLength == null) {
return;
}
if (logMessageLength.minValue != positionalArgsLength) {
wrongUsageCallback.accept(new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber,
"Expected " + logMessageLength.minValue + " arguments but got " + positionalArgsLength));
return;
}
}
private void checkArrayArgs(MethodNode methodNode, Frame<BasicValue> logMessageFrame, Frame<BasicValue> arraySizeFrame,
int lineNumber, MethodInsnNode methodInsn, int messageIndex, int arrayIndex) {
BasicValue arraySizeObject = getStackValue(arraySizeFrame, methodInsn, arrayIndex);
if (arraySizeObject instanceof ArraySizeBasicValue == false) {
wrongUsageCallback.accept(new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber,
"Could not determine size of array"));
return;
}
ArraySizeBasicValue arraySize = (ArraySizeBasicValue) arraySizeObject;
PlaceHolderStringBasicValue logMessageLength = checkLogMessageConsistency(methodNode, logMessageFrame, lineNumber, methodInsn,
messageIndex, arraySize.minValue);
if (logMessageLength == null) {
return;
}
if (arraySize.minValue != arraySize.maxValue) {
wrongUsageCallback.accept(new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber,
"Multiple parameter arrays with conflicting sizes"));
return;
}
assert logMessageLength.minValue == logMessageLength.maxValue && arraySize.minValue == arraySize.maxValue;
if (logMessageLength.minValue != arraySize.minValue) {
wrongUsageCallback.accept(new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber,
"Expected " + logMessageLength.minValue + " arguments but got " + arraySize.minValue));
return;
}
}
private PlaceHolderStringBasicValue checkLogMessageConsistency(MethodNode methodNode, Frame<BasicValue> logMessageFrame,
int lineNumber, MethodInsnNode methodInsn, int messageIndex,
int argsSize) {
BasicValue logMessageLengthObject = getStackValue(logMessageFrame, methodInsn, messageIndex);
if (logMessageLengthObject instanceof PlaceHolderStringBasicValue == false) { if (logMessageLengthObject instanceof PlaceHolderStringBasicValue == false) {
if (varArgsSize.minValue > 0) { if (argsSize > 0) {
wrongUsageCallback.accept(new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber, wrongUsageCallback.accept(new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber,
"First argument must be a string constant so that we can statically ensure proper place holder usage")); "First argument must be a string constant so that we can statically ensure proper place holder usage"));
continue;
} else { } else {
// don't check logger usage for logger.warn(someObject) as someObject will be fully logged // don't check logger usage for logger.warn(someObject)
continue;
} }
return null;
} }
PlaceHolderStringBasicValue logMessageLength = (PlaceHolderStringBasicValue) logMessageLengthObject; PlaceHolderStringBasicValue logMessageLength = (PlaceHolderStringBasicValue) logMessageLengthObject;
if (logMessageLength.minValue != logMessageLength.maxValue) { if (logMessageLength.minValue != logMessageLength.maxValue) {
wrongUsageCallback.accept(new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber, wrongUsageCallback.accept(new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber,
"Multiple log messages with conflicting number of place holders")); "Multiple log messages with conflicting number of place holders"));
continue; return null;
}
if (varArgsSize.minValue != varArgsSize.maxValue) {
wrongUsageCallback.accept(new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber,
"Multiple parameter arrays with conflicting sizes"));
continue;
}
assert logMessageLength.minValue == logMessageLength.maxValue && varArgsSize.minValue == varArgsSize.maxValue;
if (logMessageLength.minValue != varArgsSize.minValue) {
wrongUsageCallback.accept(new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber,
"Expected " + logMessageLength.minValue + " arguments but got " + varArgsSize.minValue));
continue;
}
}
} }
return logMessageLength;
} }
} }
@ -300,9 +399,10 @@ public class ESLoggerUsageChecker {
return count; return count;
} }
private static BasicValue getStackValue(Frame<BasicValue> f, int index) { private static BasicValue getStackValue(Frame<BasicValue> f, MethodInsnNode methodInsn, int index) {
int relIndex = Type.getArgumentTypes(methodInsn.desc).length - 1 - index;
int top = f.getStackSize() - 1; int top = f.getStackSize() - 1;
return index <= top ? f.getStack(top - index) : null; return relIndex <= top ? f.getStack(top - relIndex) : null;
} }
private static class IntMinMaxTrackingBasicValue extends BasicValue { private static class IntMinMaxTrackingBasicValue extends BasicValue {

View File

@ -20,31 +20,29 @@
package org.elasticsearch.test.loggerusage; package org.elasticsearch.test.loggerusage;
import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.message.Message;
import org.apache.logging.log4j.message.ParameterizedMessage; import org.apache.logging.log4j.message.ParameterizedMessage;
import org.apache.logging.log4j.util.MessageSupplier;
import org.apache.logging.log4j.util.Supplier; import org.apache.logging.log4j.util.Supplier;
import org.elasticsearch.common.SuppressLoggerChecks; import org.elasticsearch.common.SuppressLoggerChecks;
import org.elasticsearch.test.ESTestCase; import org.elasticsearch.test.ESTestCase;
import org.elasticsearch.test.loggerusage.ESLoggerUsageChecker.WrongLoggerUsage; import org.elasticsearch.test.loggerusage.ESLoggerUsageChecker.WrongLoggerUsage;
import org.hamcrest.Matchers;
import java.io.IOException; import java.io.IOException;
import java.io.InputStream; import java.io.InputStream;
import java.lang.reflect.Constructor;
import java.lang.reflect.Method; import java.lang.reflect.Method;
import java.util.ArrayList; import java.util.ArrayList;
import java.util.List; import java.util.List;
import java.util.function.Predicate; import java.util.stream.Stream;
import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.greaterThanOrEqualTo;
import static org.hamcrest.Matchers.hasItem; import static org.hamcrest.Matchers.lessThanOrEqualTo;
import static org.hamcrest.Matchers.notNullValue;
public class ESLoggerUsageTests extends ESTestCase { public class ESLoggerUsageTests extends ESTestCase {
// needed to avoid the test suite from failing for having no tests
public void testSoThatTestsDoNotFail() {
}
@AwaitsFix(bugUrl = "https://github.com/elastic/elasticsearch/issues/20243")
public void testLoggerUsageChecks() throws IOException { public void testLoggerUsageChecks() throws IOException {
for (Method method : getClass().getMethods()) { for (Method method : getClass().getMethods()) {
if (method.getDeclaringClass().equals(getClass())) { if (method.getDeclaringClass().equals(getClass())) {
@ -52,7 +50,8 @@ public class ESLoggerUsageTests extends ESTestCase {
logger.info("Checking logger usage for method {}", method.getName()); logger.info("Checking logger usage for method {}", method.getName());
InputStream classInputStream = getClass().getResourceAsStream(getClass().getSimpleName() + ".class"); InputStream classInputStream = getClass().getResourceAsStream(getClass().getSimpleName() + ".class");
List<WrongLoggerUsage> errors = new ArrayList<>(); List<WrongLoggerUsage> errors = new ArrayList<>();
ESLoggerUsageChecker.check(errors::add, classInputStream, Predicate.isEqual(method.getName())); ESLoggerUsageChecker.check(errors::add, classInputStream,
m -> m.equals(method.getName()) || m.startsWith("lambda$" + method.getName()));
if (method.getName().startsWith("checkFail")) { if (method.getName().startsWith("checkFail")) {
assertFalse("Expected " + method.getName() + " to have wrong Logger usage", errors.isEmpty()); assertFalse("Expected " + method.getName() + " to have wrong Logger usage", errors.isEmpty());
} else { } else {
@ -65,28 +64,58 @@ public class ESLoggerUsageTests extends ESTestCase {
} }
} }
@AwaitsFix(bugUrl = "https://github.com/elastic/elasticsearch/issues/20243") public void testLoggerUsageCheckerCompatibilityWithLog4j2Logger() throws NoSuchMethodException {
public void testLoggerUsageCheckerCompatibilityWithESLogger() throws NoSuchMethodException {
assertThat(ESLoggerUsageChecker.LOGGER_CLASS, equalTo(Logger.class.getName()));
assertThat(ESLoggerUsageChecker.THROWABLE_CLASS, equalTo(Throwable.class.getName()));
int varargsMethodCount = 0;
for (Method method : Logger.class.getMethods()) { for (Method method : Logger.class.getMethods()) {
if (ESLoggerUsageChecker.LOGGER_METHODS.contains(method.getName())) {
assertThat(method.getParameterTypes().length, greaterThanOrEqualTo(1));
int markerOffset = method.getParameterTypes()[0].equals(Marker.class) ? 1 : 0;
int paramLength = method.getParameterTypes().length - markerOffset;
if (method.isVarArgs()) { if (method.isVarArgs()) {
// check that logger usage checks all varargs methods assertEquals(2, paramLength);
assertThat(ESLoggerUsageChecker.LOGGER_METHODS, hasItem(method.getName())); assertEquals(String.class, method.getParameterTypes()[markerOffset]);
varargsMethodCount++; assertThat(method.getParameterTypes()[markerOffset + 1], Matchers.<Class<?>>isOneOf(Object[].class, Supplier[].class));
} } else {
} assertThat(method.getParameterTypes()[markerOffset], Matchers.<Class<?>>isOneOf(Message.class, MessageSupplier.class,
// currently we have two overloaded methods for each of debug, info, ... CharSequence.class, Object.class, String.class, Supplier.class));
// if that changes, we might want to have another look at the usage checker
assertThat(varargsMethodCount, equalTo(ESLoggerUsageChecker.LOGGER_METHODS.size() * 2));
// check that signature is same as we expect in the usage checker if (paramLength == 2) {
for (String methodName : ESLoggerUsageChecker.LOGGER_METHODS) { assertThat(method.getParameterTypes()[markerOffset + 1], Matchers.<Class<?>>isOneOf(Throwable.class, Object.class));
assertThat(Logger.class.getMethod(methodName, String.class, Object[].class), notNullValue()); if (method.getParameterTypes()[markerOffset + 1].equals(Object.class)) {
assertThat(Logger.class.getMethod(methodName, String.class, Throwable.class, Object[].class), notNullValue()); assertEquals(String.class, method.getParameterTypes()[markerOffset]);
} }
} }
if (paramLength > 2) {
assertEquals(String.class, method.getParameterTypes()[markerOffset]);
assertThat(paramLength, lessThanOrEqualTo(11));
for (int i = 1; i < paramLength; i++) {
assertEquals(Object.class, method.getParameterTypes()[markerOffset + i]);
}
}
}
}
}
for (String methodName : ESLoggerUsageChecker.LOGGER_METHODS) {
assertEquals(48, Stream.of(Logger.class.getMethods()).filter(m -> methodName.equals(m.getName())).count());
}
for (Constructor<?> constructor : ParameterizedMessage.class.getConstructors()) {
assertThat(constructor.getParameterTypes().length, greaterThanOrEqualTo(2));
assertEquals(String.class, constructor.getParameterTypes()[0]);
assertThat(constructor.getParameterTypes()[1], Matchers.<Class<?>>isOneOf(String[].class, Object[].class, Object.class));
if (constructor.getParameterTypes().length > 2) {
assertEquals(3, constructor.getParameterTypes().length);
if (constructor.getParameterTypes()[1].equals(Object.class)) {
assertEquals(Object.class, constructor.getParameterTypes()[2]);
} else {
assertEquals(Throwable.class, constructor.getParameterTypes()[2]);
}
}
}
assertEquals(5, ParameterizedMessage.class.getConstructors().length);
}
public void checkNumberOfArguments1() { public void checkNumberOfArguments1() {
logger.info("Hello {}", "world"); logger.info("Hello {}", "world");
@ -110,7 +139,6 @@ public class ESLoggerUsageTests extends ESTestCase {
} }
public void checkNumberOfArguments3() { public void checkNumberOfArguments3() {
// long argument list (> 5), emits different bytecode
logger.info("Hello {}, {}, {}, {}, {}, {}, {}", "world", 2, "third argument", 4, 5, 6, new String("last arg")); logger.info("Hello {}, {}, {}, {}, {}, {}, {}", "world", 2, "third argument", 4, 5, 6, new String("last arg"));
} }
@ -118,6 +146,30 @@ public class ESLoggerUsageTests extends ESTestCase {
logger.info("Hello {}, {}, {}, {}, {}, {}, {}", "world", 2, "third argument", 4, 5, 6, 7, new String("last arg")); logger.info("Hello {}, {}, {}, {}, {}, {}, {}", "world", 2, "third argument", 4, 5, 6, 7, new String("last arg"));
} }
public void checkNumberOfArgumentsParameterizedMessage1() {
logger.info(new ParameterizedMessage("Hello {}, {}, {}", "world", 2, "third argument"));
}
public void checkFailNumberOfArgumentsParameterizedMessage1() {
logger.info(new ParameterizedMessage("Hello {}, {}", "world", 2, "third argument"));
}
public void checkNumberOfArgumentsParameterizedMessage2() {
logger.info(new ParameterizedMessage("Hello {}, {}", "world", 2));
}
public void checkFailNumberOfArgumentsParameterizedMessage2() {
logger.info(new ParameterizedMessage("Hello {}, {}, {}", "world", 2));
}
public void checkNumberOfArgumentsParameterizedMessage3() {
logger.info((Supplier<?>) () -> new ParameterizedMessage("Hello {}, {}, {}", "world", 2, "third argument"));
}
public void checkFailNumberOfArgumentsParameterizedMessage3() {
logger.info((Supplier<?>) () -> new ParameterizedMessage("Hello {}, {}", "world", 2, "third argument"));
}
public void checkOrderOfExceptionArgument() { public void checkOrderOfExceptionArgument() {
logger.info("Hello", new Exception()); logger.info("Hello", new Exception());
} }