Fix logger usage checker for Log4j 2

With the switch to Log4j 2 throughout our code base, the logger usage checker was temporarily disabled. This commit
adapts the checks to work with Log4j 2 and re-enables the Gradle checks.

Closes #20243
This commit is contained in:
Yannick Welsch 2016-09-14 18:29:15 +02:00
parent 0151974500
commit 191fadafcc
4 changed files with 242 additions and 78 deletions

View File

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

View File

@ -21,14 +21,27 @@ import org.elasticsearch.gradle.precommit.PrecommitTasks
dependencies {
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}"
}
// https://github.com/elastic/elasticsearch/issues/20243
// loggerUsageCheck.enabled = false
loggerUsageCheck.enabled = false
forbiddenApisMain.enabled = true // disabled by parent project
forbiddenApisMain {
signaturesURLs = [PrecommitTasks.getResource('/forbidden/jdk-signatures.txt')] // does not depend on core, only jdk signatures
}
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;
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.ClassReader;
import org.objectweb.asm.ClassVisitor;
@ -52,9 +56,16 @@ import java.util.function.Consumer;
import java.util.function.Predicate;
public class ESLoggerUsageChecker {
public static final String LOGGER_CLASS = "org.elasticsearch.common.logging.ESLogger";
public static final String THROWABLE_CLASS = "java.lang.Throwable";
public static final List<String> LOGGER_METHODS = Arrays.asList("trace", "debug", "info", "warn", "error");
public static final Type LOGGER_CLASS = Type.getType(Logger.class);
public static final Type THROWABLE_CLASS = Type.getType(Throwable.class);
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";
@SuppressForbidden(reason = "command line tool")
@ -143,7 +154,7 @@ public class ESLoggerUsageChecker {
simpleClassName = simpleClassName + ".java";
StringBuilder sb = new StringBuilder();
sb.append("Bad usage of ");
sb.append(LOGGER_CLASS).append("#").append(logMethodName);
sb.append(LOGGER_CLASS.getClassName()).append("#").append(logMethodName);
sb.append(": ");
sb.append(errorMessage);
sb.append("\n\tat ");
@ -230,7 +241,7 @@ public class ESLoggerUsageChecker {
} catch (AnalyzerException 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();
AbstractInsnNode[] insns = methodNode.instructions.toArray();
int lineNumber = -1;
@ -240,52 +251,140 @@ public class ESLoggerUsageChecker {
LineNumberNode lineNumberNode = (LineNumberNode) insn;
lineNumber = lineNumberNode.line;
}
if (insn.getOpcode() == Opcodes.INVOKEVIRTUAL) {
if (insn.getOpcode() == Opcodes.INVOKEINTERFACE) {
MethodInsnNode methodInsn = (MethodInsnNode) insn;
if (Type.getObjectType(methodInsn.owner).getClassName().equals(LOGGER_CLASS) == false) {
continue;
}
if (Type.getObjectType(methodInsn.owner).equals(LOGGER_CLASS)) {
if (LOGGER_METHODS.contains(methodInsn.name) == false) {
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);
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 (varArgsSize.minValue > 0) {
if (argsSize > 0) {
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"));
continue;
} else {
// don't check logger usage for logger.warn(someObject) as someObject will be fully logged
continue;
// don't check logger usage for logger.warn(someObject)
}
return null;
}
PlaceHolderStringBasicValue logMessageLength = (PlaceHolderStringBasicValue) logMessageLengthObject;
if (logMessageLength.minValue != logMessageLength.maxValue) {
wrongUsageCallback.accept(new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber,
"Multiple log messages with conflicting number of place holders"));
continue;
}
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 null;
}
return logMessageLength;
}
}
@ -300,9 +399,10 @@ public class ESLoggerUsageChecker {
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;
return index <= top ? f.getStack(top - index) : null;
return relIndex <= top ? f.getStack(top - relIndex) : null;
}
private static class IntMinMaxTrackingBasicValue extends BasicValue {

View File

@ -20,31 +20,29 @@
package org.elasticsearch.test.loggerusage;
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.util.MessageSupplier;
import org.apache.logging.log4j.util.Supplier;
import org.elasticsearch.common.SuppressLoggerChecks;
import org.elasticsearch.test.ESTestCase;
import org.elasticsearch.test.loggerusage.ESLoggerUsageChecker.WrongLoggerUsage;
import org.hamcrest.Matchers;
import java.io.IOException;
import java.io.InputStream;
import java.lang.reflect.Constructor;
import java.lang.reflect.Method;
import java.util.ArrayList;
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.hasItem;
import static org.hamcrest.Matchers.notNullValue;
import static org.hamcrest.Matchers.greaterThanOrEqualTo;
import static org.hamcrest.Matchers.lessThanOrEqualTo;
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 {
for (Method method : getClass().getMethods()) {
if (method.getDeclaringClass().equals(getClass())) {
@ -52,7 +50,8 @@ public class ESLoggerUsageTests extends ESTestCase {
logger.info("Checking logger usage for method {}", method.getName());
InputStream classInputStream = getClass().getResourceAsStream(getClass().getSimpleName() + ".class");
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")) {
assertFalse("Expected " + method.getName() + " to have wrong Logger usage", errors.isEmpty());
} else {
@ -65,28 +64,58 @@ public class ESLoggerUsageTests extends ESTestCase {
}
}
@AwaitsFix(bugUrl = "https://github.com/elastic/elasticsearch/issues/20243")
public void testLoggerUsageCheckerCompatibilityWithESLogger() throws NoSuchMethodException {
assertThat(ESLoggerUsageChecker.LOGGER_CLASS, equalTo(Logger.class.getName()));
assertThat(ESLoggerUsageChecker.THROWABLE_CLASS, equalTo(Throwable.class.getName()));
int varargsMethodCount = 0;
public void testLoggerUsageCheckerCompatibilityWithLog4j2Logger() throws NoSuchMethodException {
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()) {
// check that logger usage checks all varargs methods
assertThat(ESLoggerUsageChecker.LOGGER_METHODS, hasItem(method.getName()));
varargsMethodCount++;
}
}
// currently we have two overloaded methods for each of debug, info, ...
// if that changes, we might want to have another look at the usage checker
assertThat(varargsMethodCount, equalTo(ESLoggerUsageChecker.LOGGER_METHODS.size() * 2));
assertEquals(2, paramLength);
assertEquals(String.class, method.getParameterTypes()[markerOffset]);
assertThat(method.getParameterTypes()[markerOffset + 1], Matchers.<Class<?>>isOneOf(Object[].class, Supplier[].class));
} else {
assertThat(method.getParameterTypes()[markerOffset], Matchers.<Class<?>>isOneOf(Message.class, MessageSupplier.class,
CharSequence.class, Object.class, String.class, Supplier.class));
// check that signature is same as we expect in the usage checker
for (String methodName : ESLoggerUsageChecker.LOGGER_METHODS) {
assertThat(Logger.class.getMethod(methodName, String.class, Object[].class), notNullValue());
assertThat(Logger.class.getMethod(methodName, String.class, Throwable.class, Object[].class), notNullValue());
if (paramLength == 2) {
assertThat(method.getParameterTypes()[markerOffset + 1], Matchers.<Class<?>>isOneOf(Throwable.class, Object.class));
if (method.getParameterTypes()[markerOffset + 1].equals(Object.class)) {
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() {
logger.info("Hello {}", "world");
@ -110,7 +139,6 @@ public class ESLoggerUsageTests extends ESTestCase {
}
public void checkNumberOfArguments3() {
// long argument list (> 5), emits different bytecode
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"));
}
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() {
logger.info("Hello", new Exception());
}