You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@lucene.apache.org by er...@apache.org on 2020/05/01 17:07:05 UTC
[lucene-solr] branch master updated: LUCENE-7788: fail precommit on
unparameterised log messages and examine for wasted work/objects
This is an automated email from the ASF dual-hosted git repository.
erick pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/lucene-solr.git
The following commit(s) were added to refs/heads/master by this push:
new 217c2fa LUCENE-7788: fail precommit on unparameterised log messages and examine for wasted work/objects
217c2fa is described below
commit 217c2faa2cd7b540d8e9933355dbd878a4d32057
Author: Erick Erickson <Er...@gmail.com>
AuthorDate: Fri May 1 13:06:57 2020 -0400
LUCENE-7788: fail precommit on unparameterised log messages and examine for wasted work/objects
---
gradle/validation/validate-log-calls.gradle | 3 +-
help/validateLogCalls.txt | 60 ++++++++++++++--------
...ExtractNamedEntitiesUpdateProcessorFactory.java | 2 +-
.../handler/dataimport/MailEntityProcessor.java | 2 +-
.../java/org/apache/solr/cloud/ZkController.java | 16 +++---
.../src/java/org/apache/solr/core/SolrConfig.java | 8 +--
.../solr/handler/admin/LukeRequestHandler.java | 4 +-
.../apache/solr/schema/FieldTypePluginLoader.java | 8 +--
.../org/apache/solr/security/HadoopAuthPlugin.java | 6 +--
.../org/apache/solr/update/SolrIndexConfig.java | 2 +-
.../java/org/apache/solr/util/SolrPluginUtils.java | 2 +-
.../apache/solr/util/xslt/TransformerProvider.java | 7 ++-
.../src/java/org/apache/solr/SolrTestCase.java | 2 +-
13 files changed, 68 insertions(+), 54 deletions(-)
diff --git a/gradle/validation/validate-log-calls.gradle b/gradle/validation/validate-log-calls.gradle
index b792e14..a81fd3b 100644
--- a/gradle/validation/validate-log-calls.gradle
+++ b/gradle/validation/validate-log-calls.gradle
@@ -53,7 +53,6 @@ class ValidateLogCallsTask extends DefaultTask {
violations.add(System.lineSeparator + msg);
errsFound++;
}
-
// We have a log.something line, check for patterns we're not fond of.
def checkLine(File file, String line, int lineNumber, String previous) {
boolean violation = false
@@ -98,7 +97,7 @@ class ValidateLogCallsTask extends DefaultTask {
level = lev.group(1).toLowerCase().trim()
}
if (logLevels.contains("log." + level) == false) {
- reportViolation(String.format("Found an unexpeted log level: %s, file: %s:%d"
+ reportViolation(String.format("Found an unexpected log level: %s, file: %s:%d"
, level, file.getAbsolutePath(), lineNumber))
}
boolean persnicketyLevel = !(level.equals("fatal") || level.equals("error") || level.equals("warn"))
diff --git a/help/validateLogCalls.txt b/help/validateLogCalls.txt
index dc1777f..e150ba8 100644
--- a/help/validateLogCalls.txt
+++ b/help/validateLogCalls.txt
@@ -1,58 +1,74 @@
Using log calls
===============
-There are several hidden gotchas when using logging. The main
-problem is that certain patterns are evaluated and objects
-constructed even if the logging level is more restrictive
-than this call. If the logging level is WARN, then the following
-log.info patterns are evaluated and never-used objects are
-created even though the message is never logged.
+There are several gotchas when logging. In particular, methods
+are called and strings are concatenated that have variables
+and objects can be constructed even if the logging level
+is more restrictive than the call. For instance, if the logging
+level is WARN, then a call like:
+log.trace("something {}", some_object.toString())
+will cause some_object.toString() to be called, then the resulting
+string is passed to log.trace() where the log level is evaluated
+and the logging call may be aborted. Any method called explicitly
+as part of a logging call is executed regardless of whether the
+message will be logged or not.
This can be very expensive as per measurements with Java Flight
Recorder. It's particularly egregious when complex operations
-are performed for, say, log.debug or trace calls, which
-are rarely actually used.
+are performed for, say, debug or trace levels, which
+are rarely reported.
+
+Here are a few patterns that generate useless strings/objects:
- log.info("some stuff " + some_object) will concatenate the
- strings and create an object. some_object is anytying except
- a string constant, i.e. something enclosed in quotes.
+ some_object.toString() and create a new string. The only
+ exception is if "some_object" is a literal string.
- log.info("some stuff {}", object.method()) will execute the
method.
- log.info("some stuff {}", object.toString()) will execute
- the toString and then throw the results away.
+ the toString and then may throw the results away.
+ log.info("some stuff{}", object)
+ is safe, the object's toString() method is called only after
+ the log/do not log decision has been made.
-----------
NOTES:
- If you're creating a logging call that has no choice but to
do something expensive, surround it with "if (log.is*Enabled)".
+ Validation will flag any situation where the level in the "if"
+ clause does not match the level of the actual call.
- Logging calls can take a bare exception, but do not
use the braces if you want the stack trace! So
log.info("stuff {}", exception) will not print the full stack,
log.info("stuff ", exception) _will_ print the full stack.
- log.inf0("stuff {} ", some_object, exception) will print the full stack.
- If you're puzzled as to why so many logging calls don't have a matching
- number of curly-braces and parameters, this is usually why if they involve
- exceptions.
+ log.info("stuff {} ", some_object, exception) will print "stuff + the result
+ of the object's toString() method" plus the full stack. If you're puzzled
+ as to why so many logging calls don't have a matching number of curly-braces
+ and parameters, this is usually why.
- When slf4j supports lambdas in logging calls (log4j2 does now),
we can use lambdas rather than "if log.is*Enabled". slf4j 2.0
- will when released.
+ will when released. This will probably mean this check has to be re-worked
+ to avoid false flags
-- warn, error, and fatal level messages are NOT flagged for parens, but will
- be flagged for containg plusses that aren't simple concatenation.
+- warn, error, and fatal level messages are NOT flagged for explicit,
+ function calls, but will be flagged if they contain plusses that aren't
+ simple concatenation. This last is something of a style check.
- You can get into some pretty convolued consructs trying to pass some of these
checks. Adding //logok, with or without spaces will cause the line to pass
- no matter what. Please use this hack sparingly.
+ no matter what. Please use this hack sparingly and be conscientious about
+ surrounding with 'if (log.is*Enabled)'.
-- String constants may be added with '+' OK, but they _must_ be literal strings.
+- String constants may be added with '+', but they _must_ be literal strings.
The compiler is smart enough to concatenate them when compiling. For example:
- log.info("some {} "+ "more nonsense {}", object1, object2) is fine.
- log.info("some{} " + " more nonsense " + object1, object2) is NOT fine.
+ log.info("some {} "+ "more nonsense {}", object1, object2) is fine
+ log.info("some{} " + " more nonsense " + object1, object2) is NOT fine (note
+ the plus in front of object1).
For a fuller discussion, see LUCENE-7788 and the other JIRAs linked
from there.
diff --git a/solr/contrib/analysis-extras/src/java/org/apache/solr/update/processor/OpenNLPExtractNamedEntitiesUpdateProcessorFactory.java b/solr/contrib/analysis-extras/src/java/org/apache/solr/update/processor/OpenNLPExtractNamedEntitiesUpdateProcessorFactory.java
index d69c367..3414d15 100644
--- a/solr/contrib/analysis-extras/src/java/org/apache/solr/update/processor/OpenNLPExtractNamedEntitiesUpdateProcessorFactory.java
+++ b/solr/contrib/analysis-extras/src/java/org/apache/solr/update/processor/OpenNLPExtractNamedEntitiesUpdateProcessorFactory.java
@@ -489,7 +489,7 @@ public class OpenNLPExtractNamedEntitiesUpdateProcessorFactory
if (matcher.find()) {
resolvedDest = matcher.replaceAll(dest);
} else {
- log.debug("srcSelector.shouldMutate(\"{}\") returned true, " +
+ log.debug("srcSelector.shouldMutate('{}') returned true, " +
"but replacement pattern did not match, field skipped.", fname);
continue;
}
diff --git a/solr/contrib/dataimporthandler-extras/src/java/org/apache/solr/handler/dataimport/MailEntityProcessor.java b/solr/contrib/dataimporthandler-extras/src/java/org/apache/solr/handler/dataimport/MailEntityProcessor.java
index d72f5fc..7c65f35 100644
--- a/solr/contrib/dataimporthandler-extras/src/java/org/apache/solr/handler/dataimport/MailEntityProcessor.java
+++ b/solr/contrib/dataimporthandler-extras/src/java/org/apache/solr/handler/dataimport/MailEntityProcessor.java
@@ -651,7 +651,7 @@ public class MailEntityProcessor extends EntityProcessorBase {
afterCrit));
if (log.isInfoEnabled()) {
- log.info("GMail server-side filter found {} messages received {} in folder "
+ log.info("GMail server-side filter found {} messages received {} in folder {}"
, afterMessages.length, afterCrit, folder.getName());
}
diff --git a/solr/core/src/java/org/apache/solr/cloud/ZkController.java b/solr/core/src/java/org/apache/solr/cloud/ZkController.java
index 9b0d3da..e60f2e4 100644
--- a/solr/core/src/java/org/apache/solr/cloud/ZkController.java
+++ b/solr/core/src/java/org/apache/solr/cloud/ZkController.java
@@ -1784,10 +1784,12 @@ public class ZkController implements Closeable {
}
String collectionName = cd.getCloudDescriptor().getCollectionName();
DocCollection collection = zkStateReader.getClusterState().getCollectionOrNull(collectionName);
- log.debug(collection == null ?
- "Collection {} not visible yet, but flagging it so a watch is registered when it becomes visible" :
- "Registering watch for collection {}",
- collectionName);
+ if (log.isDebugEnabled()) {
+ log.debug(collection == null ?
+ "Collection {} not visible yet, but flagging it so a watch is registered when it becomes visible" :
+ "Registering watch for collection {}",
+ collectionName);
+ }
} catch (KeeperException e) {
log.error("", e);
throw new ZooKeeperException(SolrException.ErrorCode.SERVER_ERROR, "", e);
@@ -2299,9 +2301,9 @@ public class ZkController implements Closeable {
if (wasRemoved) {
log.debug("Removed OnReconnect listener {}", listener);
} else {
- log.warn("Was asked to remove OnReconnect listener {}{}"
- , listener
- , ", but remove operation did not find it in the list of registered listeners.");
+ log.warn("Was asked to remove OnReconnect listener {}, but remove operation " +
+ "did not find it in the list of registered listeners."
+ , listener);
}
}
}
diff --git a/solr/core/src/java/org/apache/solr/core/SolrConfig.java b/solr/core/src/java/org/apache/solr/core/SolrConfig.java
index 64407c0..0414260 100644
--- a/solr/core/src/java/org/apache/solr/core/SolrConfig.java
+++ b/solr/core/src/java/org/apache/solr/core/SolrConfig.java
@@ -315,10 +315,10 @@ public class SolrConfig extends XmlConfigFile implements MapSerializable {
}
if (version == Version.LATEST && !versionWarningAlreadyLogged.getAndSet(true)) {
- log.warn("You should not use LATEST as luceneMatchVersion property: {}{}{}"
- , "if you use this setting, and then Solr upgrades to a newer release of Lucene, "
- , "sizable changes may happen. If precise back compatibility is important "
- , "then you should instead explicitly specify an actual Lucene version.");
+ log.warn("You should not use LATEST as luceneMatchVersion property: "
+ + "if you use this setting, and then Solr upgrades to a newer release of Lucene, "
+ + "sizable changes may happen. If precise back compatibility is important "
+ + "then you should instead explicitly specify an actual Lucene version.");
}
return version;
diff --git a/solr/core/src/java/org/apache/solr/handler/admin/LukeRequestHandler.java b/solr/core/src/java/org/apache/solr/handler/admin/LukeRequestHandler.java
index c165a33..1ed694b 100644
--- a/solr/core/src/java/org/apache/solr/handler/admin/LukeRequestHandler.java
+++ b/solr/core/src/java/org/apache/solr/handler/admin/LukeRequestHandler.java
@@ -622,8 +622,8 @@ public class LukeRequestHandler extends RequestHandlerBase
try {
return commit.getDirectory().fileLength(commit.getSegmentsFileName());
} catch (NoSuchFileException okException) {
- log.debug("Unable to determine the (optional) fileSize for the current IndexReader's segments file because it is {}{}"
- , "no longer in the Directory, this can happen if there are new commits since the Reader was opened"
+ log.debug("Unable to determine the (optional) fileSize for the current IndexReader's segments file because it is "
+ + "no longer in the Directory, this can happen if there are new commits since the Reader was opened"
, okException);
} catch (IOException strangeException) {
log.warn("Ignoring IOException wile attempting to determine the (optional) fileSize stat for the current IndexReader's segments file",
diff --git a/solr/core/src/java/org/apache/solr/schema/FieldTypePluginLoader.java b/solr/core/src/java/org/apache/solr/schema/FieldTypePluginLoader.java
index fcaf001..b676889 100644
--- a/solr/core/src/java/org/apache/solr/schema/FieldTypePluginLoader.java
+++ b/solr/core/src/java/org/apache/solr/schema/FieldTypePluginLoader.java
@@ -404,11 +404,11 @@ public final class FieldTypePluginLoader
SolrConfig.parseLuceneVersionString(configuredVersion) : schema.getDefaultLuceneMatchVersion();
if (!version.onOrAfter(Version.LUCENE_8_0_0)) {
- log.warn("{} is using deprecated {}{}{}"
+ log.warn("{} is using deprecated {}"
+ + " emulation. You should at some point declare and reindex to at least 8.0, because "
+ + "7.x emulation is deprecated and will be removed in 9.0"
, pluginClassName
- , version
- , " emulation. You should at some point declare and reindex to at least 8.0, because "
- , "7.x emulation is deprecated and will be removed in 9.0");
+ , version);
}
return version;
}
diff --git a/solr/core/src/java/org/apache/solr/security/HadoopAuthPlugin.java b/solr/core/src/java/org/apache/solr/security/HadoopAuthPlugin.java
index 36667f3..4696241 100644
--- a/solr/core/src/java/org/apache/solr/security/HadoopAuthPlugin.java
+++ b/solr/core/src/java/org/apache/solr/security/HadoopAuthPlugin.java
@@ -230,12 +230,10 @@ public class HadoopAuthPlugin extends AuthenticationPlugin {
public boolean doAuthenticate(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
throws Exception {
if (TRACE_HTTP) {
- log.info("----------HTTP Request---------{}");
+ log.info("----------HTTP Request---------");
if (log.isInfoEnabled()) {
log.info("{} : {}", request.getMethod(), request.getRequestURI());
- }
- if (log.isInfoEnabled()) {
- log.info("Query : {}", request.getQueryString());
+ log.info("Query : {}", request.getQueryString()); // logOk
}
log.info("Headers :");
Enumeration<String> headers = request.getHeaderNames();
diff --git a/solr/core/src/java/org/apache/solr/update/SolrIndexConfig.java b/solr/core/src/java/org/apache/solr/update/SolrIndexConfig.java
index 0bdfe84..c04c696 100644
--- a/solr/core/src/java/org/apache/solr/update/SolrIndexConfig.java
+++ b/solr/core/src/java/org/apache/solr/update/SolrIndexConfig.java
@@ -105,7 +105,7 @@ public class SolrIndexConfig implements MapSerializable {
public SolrIndexConfig(SolrConfig solrConfig, String prefix, SolrIndexConfig def) {
if (prefix == null) {
prefix = "indexConfig";
- log.debug("Defaulting to prefix \""+prefix+"\" for index configuration");
+ log.debug("Defaulting to prefix '{}' for index configuration", prefix);
}
if (def == null) {
diff --git a/solr/core/src/java/org/apache/solr/util/SolrPluginUtils.java b/solr/core/src/java/org/apache/solr/util/SolrPluginUtils.java
index 9bc8d25..a255f01 100644
--- a/solr/core/src/java/org/apache/solr/util/SolrPluginUtils.java
+++ b/solr/core/src/java/org/apache/solr/util/SolrPluginUtils.java
@@ -973,7 +973,7 @@ public class SolrPluginUtils {
/* we definitely had some sort of sort string from the user,
* but no SortSpec came out of it
*/
- log.warn("Invalid sort \""+sort+"\" was specified, ignoring", sortE);
+ log.warn("Invalid sort '{}' was specified, ignoring", sort, sortE);
return null;
}
diff --git a/solr/core/src/java/org/apache/solr/util/xslt/TransformerProvider.java b/solr/core/src/java/org/apache/solr/util/xslt/TransformerProvider.java
index 825a146..baae45d 100644
--- a/solr/core/src/java/org/apache/solr/util/xslt/TransformerProvider.java
+++ b/solr/core/src/java/org/apache/solr/util/xslt/TransformerProvider.java
@@ -59,10 +59,9 @@ public class TransformerProvider {
private TransformerProvider() {
// tell'em: currently, we only cache the last used XSLT transform, and blindly recompile it
// once cacheLifetimeSeconds expires
- log.warn("{}{}{}"
- , "The TransformerProvider's simplistic XSLT caching mechanism is not appropriate "
- , "for high load scenarios, unless a single XSLT transform is used"
- , " and xsltCacheLifetimeSeconds is set to a sufficiently high value.");
+ log.warn("The TransformerProvider's simplistic XSLT caching mechanism is not appropriate "
+ + "for high load scenarios, unless a single XSLT transform is used"
+ + " and xsltCacheLifetimeSeconds is set to a sufficiently high value.");
}
/** Return a new Transformer, possibly created from our cached Templates object
diff --git a/solr/test-framework/src/java/org/apache/solr/SolrTestCase.java b/solr/test-framework/src/java/org/apache/solr/SolrTestCase.java
index 3935dfe..525cd70 100644
--- a/solr/test-framework/src/java/org/apache/solr/SolrTestCase.java
+++ b/solr/test-framework/src/java/org/apache/solr/SolrTestCase.java
@@ -83,7 +83,7 @@ public class SolrTestCase extends LuceneTestCase {
public static void setDefaultConfigDirSysPropIfNotSet() {
final String existingValue = System.getProperty(SolrDispatchFilter.SOLR_DEFAULT_CONFDIR_ATTRIBUTE);
if (null != existingValue) {
- log.info("Test env includes configset dir system property '{}'='{}'");
+ log.info("Test env includes configset dir system property '{}'='{}'", SolrDispatchFilter.SOLR_DEFAULT_CONFDIR_ATTRIBUTE, existingValue);
return;
}
final File extPath = new File(ExternalPaths.DEFAULT_CONFIGSET);