From 98276111e1fdd63ce00821118fea9a1c4edef595 Mon Sep 17 00:00:00 2001 From: Yannick Welsch Date: Tue, 28 Jun 2016 15:39:59 +0200 Subject: [PATCH 1/2] Re-enable logger usage checks It was inadvertently disabled after applying code review comments. This commit reenables the logger usage checker and makes it less naggy when encountering logging usages of the form logger.info(someStringBuilder). Previously it would fail with the error message "First argument must be a string constant so that we can statically ensure proper place holder usage". Now it will only fail in case any arguments are provided as well, for example logger.info(someStringBuilder, 42). --- .../loggerusage/ESLoggerUsageChecker.java | 33 +++++++++++-------- .../test/loggerusage/ESLoggerUsageTests.java | 8 +++-- 2 files changed, 25 insertions(+), 16 deletions(-) diff --git a/test/logger-usage/src/main/java/org/elasticsearch/test/loggerusage/ESLoggerUsageChecker.java b/test/logger-usage/src/main/java/org/elasticsearch/test/loggerusage/ESLoggerUsageChecker.java index 25d4052c162..041d21cc762 100644 --- a/test/logger-usage/src/main/java/org/elasticsearch/test/loggerusage/ESLoggerUsageChecker.java +++ b/test/logger-usage/src/main/java/org/elasticsearch/test/loggerusage/ESLoggerUsageChecker.java @@ -82,7 +82,7 @@ public class ESLoggerUsageChecker { Files.walkFileTree(root, new SimpleFileVisitor() { @Override public FileVisitResult visitFile(Path file, BasicFileAttributes attrs) throws IOException { - if (Files.isRegularFile(file) && file.endsWith(".class")) { + if (Files.isRegularFile(file) && file.getFileName().toString().endsWith(".class")) { try (InputStream in = Files.newInputStream(file)) { ESLoggerUsageChecker.check(wrongUsageCallback, in); } @@ -248,19 +248,6 @@ public class ESLoggerUsageChecker { if (LOGGER_METHODS.contains(methodInsn.name) == false) { continue; } - Type[] argumentTypes = Type.getArgumentTypes(methodInsn.desc); - BasicValue logMessageLengthObject = getStackValue(stringFrames[i], argumentTypes.length - 1); // first argument - if (logMessageLengthObject instanceof PlaceHolderStringBasicValue == false) { - 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; - } - 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; - } BasicValue varArgsSizeObject = getStackValue(arraySizeFrames[i], 0); // last argument if (varArgsSizeObject instanceof ArraySizeBasicValue == false) { wrongUsageCallback.accept(new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber, @@ -268,6 +255,24 @@ public class ESLoggerUsageChecker { continue; } ArraySizeBasicValue varArgsSize = (ArraySizeBasicValue) varArgsSizeObject; + Type[] argumentTypes = Type.getArgumentTypes(methodInsn.desc); + BasicValue logMessageLengthObject = getStackValue(stringFrames[i], argumentTypes.length - 1); // first argument + if (logMessageLengthObject instanceof PlaceHolderStringBasicValue == false) { + if (varArgsSize.minValue > 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; + } + } + 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")); diff --git a/test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/ESLoggerUsageTests.java b/test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/ESLoggerUsageTests.java index ab07ecbf45e..73449f4351c 100644 --- a/test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/ESLoggerUsageTests.java +++ b/test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/ESLoggerUsageTests.java @@ -129,8 +129,12 @@ public class ESLoggerUsageTests extends ESTestCase { logger.info("Hello {}, {}", "world", 42, new Exception()); } - public void checkFailNonConstantMessage(boolean b) { - logger.info(Boolean.toString(b)); + public void checkNonConstantMessageWithZeroArguments(boolean b) { + logger.info(Boolean.toString(b), new Exception()); + } + + public void checkFailNonConstantMessageWithArguments(boolean b) { + logger.info(Boolean.toString(b), new Exception(), 42); } public void checkComplexUsage(boolean b) { From 051579184633030a07b1df08bedb16f6c7ade30c Mon Sep 17 00:00:00 2001 From: Yannick Welsch Date: Tue, 28 Jun 2016 15:49:00 +0200 Subject: [PATCH 2/2] Fix logger usages --- .../search/AbstractSearchAsyncAction.java | 23 +++++-------------- .../SearchScrollQueryAndFetchAsyncAction.java | 4 ++-- ...SearchScrollQueryThenFetchAsyncAction.java | 2 +- .../cluster/NodeConnectionsService.java | 2 +- .../common/logging/ESLogger.java | 2 ++ .../zen/elect/ElectMasterService.java | 9 ++++---- .../elasticsearch/threadpool/ThreadPool.java | 2 +- .../bootstrap/MaxMapCountCheckTests.java | 2 ++ .../cluster/routing/PrimaryTermsTests.java | 4 ++-- .../AbstractLifecycleRunnableTests.java | 2 ++ .../gateway/GatewayIndexStateIT.java | 2 +- .../store/IndicesStoreIntegrationIT.java | 2 +- .../elasticsearch/recovery/RelocationIT.java | 2 +- .../AbstractAsyncBulkByScrollAction.java | 2 +- 14 files changed, 27 insertions(+), 33 deletions(-) diff --git a/core/src/main/java/org/elasticsearch/action/search/AbstractSearchAsyncAction.java b/core/src/main/java/org/elasticsearch/action/search/AbstractSearchAsyncAction.java index 805d09a0830..d843d8c0630 100644 --- a/core/src/main/java/org/elasticsearch/action/search/AbstractSearchAsyncAction.java +++ b/core/src/main/java/org/elasticsearch/action/search/AbstractSearchAsyncAction.java @@ -190,7 +190,7 @@ abstract class AbstractSearchAsyncAction innerMoveToSecondPhase(); } catch (Throwable e) { if (logger.isDebugEnabled()) { - logger.debug(shardIt.shardId() + ": Failed to execute [" + request + "] while moving to second phase", e); + logger.debug("{}: Failed to execute [{}] while moving to second phase", e, shardIt.shardId(), request); } raiseEarlyFailure(new ReduceSearchPhaseException(firstPhaseName(), "", e, buildShardFailures())); } @@ -210,11 +210,7 @@ abstract class AbstractSearchAsyncAction if (totalOps.incrementAndGet() == expectedTotalOps) { if (logger.isDebugEnabled()) { if (t != null && !TransportActions.isShardNotAvailableException(t)) { - if (shard != null) { - logger.debug(shard.shortSummary() + ": Failed to execute [" + request + "]", t); - } else { - logger.debug(shardIt.shardId() + ": Failed to execute [" + request + "]", t); - } + logger.debug("{}: Failed to execute [{}]", t, shard != null ? shard.shortSummary() : shardIt.shardId(), request); } else if (logger.isTraceEnabled()) { logger.trace("{}: Failed to execute [{}]", t, shard, request); } @@ -239,7 +235,8 @@ abstract class AbstractSearchAsyncAction final boolean lastShard = nextShard == null; // trace log this exception if (logger.isTraceEnabled()) { - logger.trace(executionFailureMsg(shard, shardIt, request, lastShard), t); + logger.trace("{}: Failed to execute [{}] lastShard [{}]", t, shard != null ? shard.shortSummary() : shardIt.shardId(), + request, lastShard); } if (!lastShard) { try { @@ -251,22 +248,14 @@ abstract class AbstractSearchAsyncAction // no more shards active, add a failure if (logger.isDebugEnabled() && !logger.isTraceEnabled()) { // do not double log this exception if (t != null && !TransportActions.isShardNotAvailableException(t)) { - logger.debug(executionFailureMsg(shard, shardIt, request, lastShard), t); + logger.debug("{}: Failed to execute [{}] lastShard [{}]", t, + shard != null ? shard.shortSummary() : shardIt.shardId(), request, lastShard); } } } } } - private String executionFailureMsg(@Nullable ShardRouting shard, final ShardIterator shardIt, SearchRequest request, - boolean lastShard) { - if (shard != null) { - return shard.shortSummary() + ": Failed to execute [" + request + "] lastShard [" + lastShard + "]"; - } else { - return shardIt.shardId() + ": Failed to execute [" + request + "] lastShard [" + lastShard + "]"; - } - } - protected final ShardSearchFailure[] buildShardFailures() { AtomicArray shardFailures = this.shardFailures; if (shardFailures == null) { diff --git a/core/src/main/java/org/elasticsearch/action/search/SearchScrollQueryAndFetchAsyncAction.java b/core/src/main/java/org/elasticsearch/action/search/SearchScrollQueryAndFetchAsyncAction.java index 4e0ee3ff5e5..90bb0937327 100644 --- a/core/src/main/java/org/elasticsearch/action/search/SearchScrollQueryAndFetchAsyncAction.java +++ b/core/src/main/java/org/elasticsearch/action/search/SearchScrollQueryAndFetchAsyncAction.java @@ -103,7 +103,7 @@ class SearchScrollQueryAndFetchAsyncAction extends AbstractAsyncAction { executePhase(i, node, target.getScrollId()); } else { if (logger.isDebugEnabled()) { - logger.debug("Node [" + target.getNode() + "] not available for scroll request [" + scrollId.getSource() + "]"); + logger.debug("Node [{}] not available for scroll request [{}]", target.getNode(), scrollId.getSource()); } successfulOps.decrementAndGet(); if (counter.decrementAndGet() == 0) { @@ -116,7 +116,7 @@ class SearchScrollQueryAndFetchAsyncAction extends AbstractAsyncAction { DiscoveryNode node = nodes.get(target.getNode()); if (node == null) { if (logger.isDebugEnabled()) { - logger.debug("Node [" + target.getNode() + "] not available for scroll request [" + scrollId.getSource() + "]"); + logger.debug("Node [{}] not available for scroll request [{}]", target.getNode(), scrollId.getSource()); } successfulOps.decrementAndGet(); if (counter.decrementAndGet() == 0) { diff --git a/core/src/main/java/org/elasticsearch/action/search/SearchScrollQueryThenFetchAsyncAction.java b/core/src/main/java/org/elasticsearch/action/search/SearchScrollQueryThenFetchAsyncAction.java index 8e822302d2f..694ee16beac 100644 --- a/core/src/main/java/org/elasticsearch/action/search/SearchScrollQueryThenFetchAsyncAction.java +++ b/core/src/main/java/org/elasticsearch/action/search/SearchScrollQueryThenFetchAsyncAction.java @@ -107,7 +107,7 @@ class SearchScrollQueryThenFetchAsyncAction extends AbstractAsyncAction { executeQueryPhase(i, counter, node, target.getScrollId()); } else { if (logger.isDebugEnabled()) { - logger.debug("Node [" + target.getNode() + "] not available for scroll request [" + scrollId.getSource() + "]"); + logger.debug("Node [{}] not available for scroll request [{}]", target.getNode(), scrollId.getSource()); } successfulOps.decrementAndGet(); if (counter.decrementAndGet() == 0) { diff --git a/core/src/main/java/org/elasticsearch/cluster/NodeConnectionsService.java b/core/src/main/java/org/elasticsearch/cluster/NodeConnectionsService.java index 698f9d1090c..404ae57d5f7 100644 --- a/core/src/main/java/org/elasticsearch/cluster/NodeConnectionsService.java +++ b/core/src/main/java/org/elasticsearch/cluster/NodeConnectionsService.java @@ -91,7 +91,7 @@ public class NodeConnectionsService extends AbstractLifecycleComponent runCallable = mock(Callable.class); diff --git a/core/src/test/java/org/elasticsearch/gateway/GatewayIndexStateIT.java b/core/src/test/java/org/elasticsearch/gateway/GatewayIndexStateIT.java index 049fd90cad6..129495ea15e 100644 --- a/core/src/test/java/org/elasticsearch/gateway/GatewayIndexStateIT.java +++ b/core/src/test/java/org/elasticsearch/gateway/GatewayIndexStateIT.java @@ -343,7 +343,7 @@ public class GatewayIndexStateIT extends ESIntegTestCase { } else { // test with a shadow replica index final Path dataPath = createTempDir(); - logger.info("--> created temp data path for shadow replicas [" + dataPath + "]"); + logger.info("--> created temp data path for shadow replicas [{}]", dataPath); logger.info("--> starting a cluster with " + numNodes + " nodes"); final Settings nodeSettings = Settings.builder() .put("node.add_id_to_custom_path", false) diff --git a/core/src/test/java/org/elasticsearch/indices/store/IndicesStoreIntegrationIT.java b/core/src/test/java/org/elasticsearch/indices/store/IndicesStoreIntegrationIT.java index b500ffb7dd2..b4f66c2e17b 100644 --- a/core/src/test/java/org/elasticsearch/indices/store/IndicesStoreIntegrationIT.java +++ b/core/src/test/java/org/elasticsearch/indices/store/IndicesStoreIntegrationIT.java @@ -263,7 +263,7 @@ public class IndicesStoreIntegrationIT extends ESIntegTestCase { assertThat(waitForShardDeletion(node_3, index, 0), equalTo(false)); Path server2Shard = shardDirectory(node_2, index, 0); - logger.info("--> stopping node " + node_2); + logger.info("--> stopping node {}", node_2); internalCluster().stopRandomNode(InternalTestCluster.nameFilter(node_2)); logger.info("--> running cluster_health"); diff --git a/core/src/test/java/org/elasticsearch/recovery/RelocationIT.java b/core/src/test/java/org/elasticsearch/recovery/RelocationIT.java index bc9909b21c1..620dfeb94c2 100644 --- a/core/src/test/java/org/elasticsearch/recovery/RelocationIT.java +++ b/core/src/test/java/org/elasticsearch/recovery/RelocationIT.java @@ -479,7 +479,7 @@ public class RelocationIT extends ESIntegTestCase { indexRandom(true, docs); numDocs *= 2; - logger.info(" --> waiting for relocation to complete", numDocs); + logger.info(" --> waiting for relocation to complete"); ensureGreen("test");// move all shards to the new node (it waits on relocation) final int numIters = randomIntBetween(10, 20); for (int i = 0; i < numIters; i++) { diff --git a/modules/reindex/src/main/java/org/elasticsearch/index/reindex/AbstractAsyncBulkByScrollAction.java b/modules/reindex/src/main/java/org/elasticsearch/index/reindex/AbstractAsyncBulkByScrollAction.java index ceb00b2f81f..3403a8077b9 100644 --- a/modules/reindex/src/main/java/org/elasticsearch/index/reindex/AbstractAsyncBulkByScrollAction.java +++ b/modules/reindex/src/main/java/org/elasticsearch/index/reindex/AbstractAsyncBulkByScrollAction.java @@ -404,7 +404,7 @@ public abstract class AbstractAsyncBulkByScrollAction