Disallow logger methods with Object parameter (#28969)

ywelsch · web-flow · commit be7f5dde2423 · 2018-03-12T03:05:24.000-07:00
Log4j2 provides a wide range of logging methods. Our code typically only uses a subset of them. In particular, uses of the methods trace|debug|info|warn|error|fatal(Object) or trace|debug|info|warn|error|fatal(Object, Throwable) have all been wrong, leading to not properly logging the provided message. To prevent these issues in the future, the corresponding Logger methods have been blacklisted.
diff --git a/buildSrc/src/main/resources/forbidden/es-server-signatures.txt b/buildSrc/src/main/resources/forbidden/es-server-signatures.txt
@@ -133,3 +133,17 @@ java.time.OffsetDateTime#withYear(int)
 java.time.zone.ZoneRules#getStandardOffset(java.time.Instant)
 java.time.zone.ZoneRules#getDaylightSavings(java.time.Instant)
 java.time.zone.ZoneRules#isDaylightSavings(java.time.Instant)
+
+@defaultMessage Use logger methods with non-Object parameter
+org.apache.logging.log4j.Logger#trace(java.lang.Object)
+org.apache.logging.log4j.Logger#trace(java.lang.Object, java.lang.Throwable)
+org.apache.logging.log4j.Logger#debug(java.lang.Object)
+org.apache.logging.log4j.Logger#debug(java.lang.Object, java.lang.Throwable)
+org.apache.logging.log4j.Logger#info(java.lang.Object)
+org.apache.logging.log4j.Logger#info(java.lang.Object, java.lang.Throwable)
+org.apache.logging.log4j.Logger#warn(java.lang.Object)
+org.apache.logging.log4j.Logger#warn(java.lang.Object, java.lang.Throwable)
+org.apache.logging.log4j.Logger#error(java.lang.Object)
+org.apache.logging.log4j.Logger#error(java.lang.Object, java.lang.Throwable)
+org.apache.logging.log4j.Logger#fatal(java.lang.Object)
+org.apache.logging.log4j.Logger#fatal(java.lang.Object, java.lang.Throwable)
diff --git a/server/src/main/java/org/elasticsearch/common/util/concurrent/QueueResizingEsThreadPoolExecutor.java b/server/src/main/java/org/elasticsearch/common/util/concurrent/QueueResizingEsThreadPoolExecutor.java
@@ -197,7 +197,7 @@ protected void afterExecute(Runnable r, Throwable t) {
                 }
             } catch (ArithmeticException e) {
                 // There was an integer overflow, so just log about it, rather than adjust the queue size
-                logger.warn((Supplier<?>) () -> new ParameterizedMessage(
+                logger.warn(() -> new ParameterizedMessage(
                                 "failed to calculate optimal queue size for [{}] thread pool, " +
                                 "total frame time [{}ns], tasks [{}], task execution time [{}ns]",
                                 getName(), totalRuntime, tasksPerFrame, totalNanos),
diff --git a/server/src/main/java/org/elasticsearch/index/IndexService.java b/server/src/main/java/org/elasticsearch/index/IndexService.java
@@ -448,7 +448,7 @@ private void closeShard(String reason, ShardId sId, IndexShard indexShard, Store
                 }
             } catch (Exception e) {
                 logger.warn(
-                    (Supplier<?>) () -> new ParameterizedMessage(
+                    () -> new ParameterizedMessage(
                         "[{}] failed to close store on shard removal (reason: [{}])", shardId, reason), e);
             }
         }
@@ -467,7 +467,7 @@ private void onShardClose(ShardLock lock) {
             } catch (IOException e) {
                 shardStoreDeleter.addPendingDelete(lock.getShardId(), indexSettings);
                 logger.debug(
-                    (Supplier<?>) () -> new ParameterizedMessage(
+                    () -> new ParameterizedMessage(
                         "[{}] failed to delete shard content - scheduled a retry", lock.getShardId().id()), e);
             }
         }
@@ -623,7 +623,7 @@ public synchronized void updateMetaData(final IndexMetaData metadata) {
                     shard.onSettingsChanged();
                 } catch (Exception e) {
                     logger.warn(
-                        (Supplier<?>) () -> new ParameterizedMessage(
+                        () -> new ParameterizedMessage(
                             "[{}] failed to notify shard about setting change", shard.shardId().id()), e);
                 }
             }
@@ -832,7 +832,7 @@ public final void run() {
                 if (lastThrownException == null || sameException(lastThrownException, ex) == false) {
                     // prevent the annoying fact of logging the same stuff all the time with an interval of 1 sec will spam all your logs
                     indexService.logger.warn(
-                        (Supplier<?>) () -> new ParameterizedMessage(
+                        () -> new ParameterizedMessage(
                             "failed to run task {} - suppressing re-occurring exceptions unless the exception changes",
                             toString()),
                         ex);
diff --git a/server/src/main/java/org/elasticsearch/indices/IndicesService.java b/server/src/main/java/org/elasticsearch/indices/IndicesService.java
@@ -311,7 +311,7 @@ Map<Index, List<IndexShardStats>> statsByShard(final IndicesService indicesServi
                     }
                 } catch (IllegalIndexShardStateException | AlreadyClosedException e) {
                     // we can safely ignore illegal state on ones that are closing for example
-                    logger.trace((Supplier<?>) () -> new ParameterizedMessage("{} ignoring shard stats", indexShard.shardId()), e);
+                    logger.trace(() -> new ParameterizedMessage("{} ignoring shard stats", indexShard.shardId()), e);
                 }
             }
         }
@@ -561,7 +561,7 @@ public void removeIndex(final Index index, final IndexRemovalReason reason, fina
                 deleteIndexStore(extraInfo, indexService.index(), indexSettings);
             }
         } catch (Exception e) {
-            logger.warn((Supplier<?>) () -> new ParameterizedMessage("failed to remove index {} ([{}][{}])", index, reason, extraInfo), e);
+            logger.warn(() -> new ParameterizedMessage("failed to remove index {} ([{}][{}])", index, reason, extraInfo), e);
         }
     }
 
@@ -617,7 +617,7 @@ public void deleteUnassignedIndex(String reason, IndexMetaData metaData, Cluster
                 }
                 deleteIndexStore(reason, metaData, clusterState);
             } catch (Exception e) {
-                logger.warn((Supplier<?>) () -> new ParameterizedMessage("[{}] failed to delete unassigned index (reason [{}])", metaData.getIndex(), reason), e);
+                logger.warn(() -> new ParameterizedMessage("[{}] failed to delete unassigned index (reason [{}])", metaData.getIndex(), reason), e);
             }
         }
     }
@@ -669,9 +669,9 @@ private void deleteIndexStoreIfDeletionAllowed(final String reason, final Index
             }
             success = true;
         } catch (LockObtainFailedException ex) {
-            logger.debug((Supplier<?>) () -> new ParameterizedMessage("{} failed to delete index store - at least one shards is still locked", index), ex);
+            logger.debug(() -> new ParameterizedMessage("{} failed to delete index store - at least one shards is still locked", index), ex);
         } catch (Exception ex) {
-            logger.warn((Supplier<?>) () -> new ParameterizedMessage("{} failed to delete index", index), ex);
+            logger.warn(() -> new ParameterizedMessage("{} failed to delete index", index), ex);
         } finally {
             if (success == false) {
                 addPendingDelete(index, indexSettings);
@@ -774,7 +774,7 @@ public IndexMetaData verifyIndexIsDeleted(final Index index, final ClusterState
             try {
                 metaData = metaStateService.loadIndexState(index);
             } catch (Exception e) {
-                logger.warn((Supplier<?>) () -> new ParameterizedMessage("[{}] failed to load state file from a stale deleted index, folders will be left on disk", index), e);
+                logger.warn(() -> new ParameterizedMessage("[{}] failed to load state file from a stale deleted index, folders will be left on disk", index), e);
                 return null;
             }
             final IndexSettings indexSettings = buildIndexSettings(metaData);
@@ -783,7 +783,7 @@ public IndexMetaData verifyIndexIsDeleted(final Index index, final ClusterState
             } catch (Exception e) {
                 // we just warn about the exception here because if deleteIndexStoreIfDeletionAllowed
                 // throws an exception, it gets added to the list of pending deletes to be tried again
-                logger.warn((Supplier<?>) () -> new ParameterizedMessage("[{}] failed to delete index on disk", metaData.getIndex()), e);
+                logger.warn(() -> new ParameterizedMessage("[{}] failed to delete index on disk", metaData.getIndex()), e);
             }
             return metaData;
         }
@@ -960,7 +960,7 @@ public void processPendingDeletes(Index index, IndexSettings indexSettings, Time
                                 nodeEnv.deleteIndexDirectoryUnderLock(index, indexSettings);
                                 iterator.remove();
                             } catch (IOException ex) {
-                                logger.debug((Supplier<?>) () -> new ParameterizedMessage("{} retry pending delete", index), ex);
+                                logger.debug(() -> new ParameterizedMessage("{} retry pending delete", index), ex);
                             }
                         } else {
                             assert delete.shardId != -1;
@@ -970,7 +970,7 @@ public void processPendingDeletes(Index index, IndexSettings indexSettings, Time
                                     deleteShardStore("pending delete", shardLock, delete.settings);
                                     iterator.remove();
                                 } catch (IOException ex) {
-                                    logger.debug((Supplier<?>) () -> new ParameterizedMessage("{} retry pending delete", shardLock.getShardId()), ex);
+                                    logger.debug(() -> new ParameterizedMessage("{} retry pending delete", shardLock.getShardId()), ex);
                                 }
                             } else {
                                 logger.warn("{} no shard lock for pending delete", delete.shardId);
diff --git a/server/src/main/java/org/elasticsearch/rest/RestController.java b/server/src/main/java/org/elasticsearch/rest/RestController.java
@@ -177,7 +177,7 @@ public void dispatchRequest(RestRequest request, RestChannel channel, ThreadCont
                 channel.sendResponse(new BytesRestResponse(channel, e));
             } catch (Exception inner) {
                 inner.addSuppressed(e);
-                logger.error((Supplier<?>) () ->
+                logger.error(() ->
                     new ParameterizedMessage("failed to send failure response for uri [{}]", request.uri()), inner);
             }
         }
diff --git a/server/src/main/java/org/elasticsearch/transport/TransportService.java b/server/src/main/java/org/elasticsearch/transport/TransportService.java
@@ -249,15 +249,15 @@ protected void doStop() {
                         public void onRejection(Exception e) {
                             // if we get rejected during node shutdown we don't wanna bubble it up
                             logger.debug(
-                                (Supplier<?>) () -> new ParameterizedMessage(
+                                () -> new ParameterizedMessage(
                                     "failed to notify response handler on rejection, action: {}",
                                     holderToNotify.action()),
                                 e);
                         }
                         @Override
                         public void onFailure(Exception e) {
                             logger.warn(
-                                (Supplier<?>) () -> new ParameterizedMessage(
+                                () -> new ParameterizedMessage(
                                     "failed to notify response handler on exception, action: {}",
                                     holderToNotify.action()),
                                 e);
@@ -611,15 +611,15 @@ private <T extends TransportResponse> void sendRequestInternal(final Transport.C
                     public void onRejection(Exception e) {
                         // if we get rejected during node shutdown we don't wanna bubble it up
                         logger.debug(
-                            (Supplier<?>) () -> new ParameterizedMessage(
+                            () -> new ParameterizedMessage(
                                 "failed to notify response handler on rejection, action: {}",
                                 holderToNotify.action()),
                             e);
                     }
                     @Override
                     public void onFailure(Exception e) {
                         logger.warn(
-                            (Supplier<?>) () -> new ParameterizedMessage(
+                            () -> new ParameterizedMessage(
                                 "failed to notify response handler on exception, action: {}",
                                 holderToNotify.action()),
                             e);
@@ -667,8 +667,7 @@ public void onFailure(Exception e) {
                             channel.sendResponse(e);
                         } catch (Exception inner) {
                             inner.addSuppressed(e);
-                            logger.warn(
-                                (Supplier<?>) () -> new ParameterizedMessage(
+                            logger.warn(() -> new ParameterizedMessage(
                                     "failed to notify channel of error message for action [{}]", action), inner);
                         }
                     }
@@ -681,7 +680,7 @@ public void onFailure(Exception e) {
             } catch (Exception inner) {
                 inner.addSuppressed(e);
                 logger.warn(
-                    (Supplier<?>) () -> new ParameterizedMessage(
+                    () -> new ParameterizedMessage(
                         "failed to notify channel of error message for action [{}]", action), inner);
             }
         }
@@ -1191,7 +1190,7 @@ protected void processException(final TransportResponseHandler handler, final Re
                 handler.handleException(rtx);
             } catch (Exception e) {
                 logger.error(
-                    (Supplier<?>) () -> new ParameterizedMessage(
+                    () -> new ParameterizedMessage(
                         "failed to handle exception for action [{}], handler [{}]", action, handler), e);
             }
         }

Original file line number	Diff line number	Diff line change
`@@ -197,7 +197,7 @@ protected void afterExecute(Runnable r, Throwable t) {`
`197`	`197`	`}`
`198`	`198`	`} catch (ArithmeticException e) {`
`199`	`199`	`// There was an integer overflow, so just log about it, rather than adjust the queue size`
`200`		`- logger.warn((Supplier<?>) () -> new ParameterizedMessage(`
	`200`	`+ logger.warn(() -> new ParameterizedMessage(`
`201`	`201`	`"failed to calculate optimal queue size for [{}] thread pool, " +`
`202`	`202`	`"total frame time [{}ns], tasks [{}], task execution time [{}ns]",`
`203`	`203`	`getName(), totalRuntime, tasksPerFrame, totalNanos),`
Original file line number	Diff line number	Diff line change
`@@ -448,7 +448,7 @@ private void closeShard(String reason, ShardId sId, IndexShard indexShard, Store`
`448`	`448`	`}`
`449`	`449`	`} catch (Exception e) {`
`450`	`450`	`logger.warn(`
`451`		`- (Supplier<?>) () -> new ParameterizedMessage(`
	`451`	`+ () -> new ParameterizedMessage(`
`452`	`452`	`"[{}] failed to close store on shard removal (reason: [{}])", shardId, reason), e);`
`453`	`453`	`}`
`454`	`454`	`}`
`@@ -467,7 +467,7 @@ private void onShardClose(ShardLock lock) {`
`467`	`467`	`} catch (IOException e) {`
`468`	`468`	`shardStoreDeleter.addPendingDelete(lock.getShardId(), indexSettings);`
`469`	`469`	`logger.debug(`
`470`		`- (Supplier<?>) () -> new ParameterizedMessage(`
	`470`	`+ () -> new ParameterizedMessage(`
`471`	`471`	`"[{}] failed to delete shard content - scheduled a retry", lock.getShardId().id()), e);`
`472`	`472`	`}`
`473`	`473`	`}`
`@@ -623,7 +623,7 @@ public synchronized void updateMetaData(final IndexMetaData metadata) {`
`623`	`623`	`shard.onSettingsChanged();`
`624`	`624`	`} catch (Exception e) {`
`625`	`625`	`logger.warn(`
`626`		`- (Supplier<?>) () -> new ParameterizedMessage(`
	`626`	`+ () -> new ParameterizedMessage(`
`627`	`627`	`"[{}] failed to notify shard about setting change", shard.shardId().id()), e);`
`628`	`628`	`}`
`629`	`629`	`}`
`@@ -832,7 +832,7 @@ public final void run() {`
`832`	`832`	`if (lastThrownException == null \|\| sameException(lastThrownException, ex) == false) {`
`833`	`833`	`// prevent the annoying fact of logging the same stuff all the time with an interval of 1 sec will spam all your logs`
`834`	`834`	`indexService.logger.warn(`
`835`		`- (Supplier<?>) () -> new ParameterizedMessage(`
	`835`	`+ () -> new ParameterizedMessage(`
`836`	`836`	`"failed to run task {} - suppressing re-occurring exceptions unless the exception changes",`
`837`	`837`	`toString()),`
`838`	`838`	`ex);`
Original file line number	Diff line number	Diff line change
`@@ -311,7 +311,7 @@ Map<Index, List<IndexShardStats>> statsByShard(final IndicesService indicesServi`
`311`	`311`	`}`
`312`	`312`	`} catch (IllegalIndexShardStateException \| AlreadyClosedException e) {`
`313`	`313`	`// we can safely ignore illegal state on ones that are closing for example`
`314`		`- logger.trace((Supplier<?>) () -> new ParameterizedMessage("{} ignoring shard stats", indexShard.shardId()), e);`
	`314`	`+ logger.trace(() -> new ParameterizedMessage("{} ignoring shard stats", indexShard.shardId()), e);`
`315`	`315`	`}`
`316`	`316`	`}`
`317`	`317`	`}`
`@@ -561,7 +561,7 @@ public void removeIndex(final Index index, final IndexRemovalReason reason, fina`
`561`	`561`	`deleteIndexStore(extraInfo, indexService.index(), indexSettings);`
`562`	`562`	`}`
`563`	`563`	`} catch (Exception e) {`
`564`		`- logger.warn((Supplier<?>) () -> new ParameterizedMessage("failed to remove index {} ([{}][{}])", index, reason, extraInfo), e);`
	`564`	`+ logger.warn(() -> new ParameterizedMessage("failed to remove index {} ([{}][{}])", index, reason, extraInfo), e);`
`565`	`565`	`}`
`566`	`566`	`}`
`567`	`567`
`@@ -617,7 +617,7 @@ public void deleteUnassignedIndex(String reason, IndexMetaData metaData, Cluster`
`617`	`617`	`}`
`618`	`618`	`deleteIndexStore(reason, metaData, clusterState);`
`619`	`619`	`} catch (Exception e) {`
`620`		`- logger.warn((Supplier<?>) () -> new ParameterizedMessage("[{}] failed to delete unassigned index (reason [{}])", metaData.getIndex(), reason), e);`
	`620`	`+ logger.warn(() -> new ParameterizedMessage("[{}] failed to delete unassigned index (reason [{}])", metaData.getIndex(), reason), e);`
`621`	`621`	`}`
`622`	`622`	`}`
`623`	`623`	`}`
`@@ -669,9 +669,9 @@ private void deleteIndexStoreIfDeletionAllowed(final String reason, final Index`
`669`	`669`	`}`
`670`	`670`	`success = true;`
`671`	`671`	`} catch (LockObtainFailedException ex) {`
`672`		`- logger.debug((Supplier<?>) () -> new ParameterizedMessage("{} failed to delete index store - at least one shards is still locked", index), ex);`
	`672`	`+ logger.debug(() -> new ParameterizedMessage("{} failed to delete index store - at least one shards is still locked", index), ex);`
`673`	`673`	`} catch (Exception ex) {`
`674`		`- logger.warn((Supplier<?>) () -> new ParameterizedMessage("{} failed to delete index", index), ex);`
	`674`	`+ logger.warn(() -> new ParameterizedMessage("{} failed to delete index", index), ex);`
`675`	`675`	`} finally {`
`676`	`676`	`if (success == false) {`
`677`	`677`	`addPendingDelete(index, indexSettings);`
`@@ -774,7 +774,7 @@ public IndexMetaData verifyIndexIsDeleted(final Index index, final ClusterState`
`774`	`774`	`try {`
`775`	`775`	`metaData = metaStateService.loadIndexState(index);`
`776`	`776`	`} catch (Exception e) {`
`777`		`- logger.warn((Supplier<?>) () -> new ParameterizedMessage("[{}] failed to load state file from a stale deleted index, folders will be left on disk", index), e);`
	`777`	`+ logger.warn(() -> new ParameterizedMessage("[{}] failed to load state file from a stale deleted index, folders will be left on disk", index), e);`
`778`	`778`	`return null;`
`779`	`779`	`}`
`780`	`780`	`final IndexSettings indexSettings = buildIndexSettings(metaData);`
`@@ -783,7 +783,7 @@ public IndexMetaData verifyIndexIsDeleted(final Index index, final ClusterState`
`783`	`783`	`} catch (Exception e) {`
`784`	`784`	`// we just warn about the exception here because if deleteIndexStoreIfDeletionAllowed`
`785`	`785`	`// throws an exception, it gets added to the list of pending deletes to be tried again`
`786`		`- logger.warn((Supplier<?>) () -> new ParameterizedMessage("[{}] failed to delete index on disk", metaData.getIndex()), e);`
	`786`	`+ logger.warn(() -> new ParameterizedMessage("[{}] failed to delete index on disk", metaData.getIndex()), e);`
`787`	`787`	`}`
`788`	`788`	`return metaData;`
`789`	`789`	`}`
`@@ -960,7 +960,7 @@ public void processPendingDeletes(Index index, IndexSettings indexSettings, Time`
`960`	`960`	`nodeEnv.deleteIndexDirectoryUnderLock(index, indexSettings);`
`961`	`961`	`iterator.remove();`
`962`	`962`	`} catch (IOException ex) {`
`963`		`- logger.debug((Supplier<?>) () -> new ParameterizedMessage("{} retry pending delete", index), ex);`
	`963`	`+ logger.debug(() -> new ParameterizedMessage("{} retry pending delete", index), ex);`
`964`	`964`	`}`
`965`	`965`	`} else {`
`966`	`966`	`assert delete.shardId != -1;`
`@@ -970,7 +970,7 @@ public void processPendingDeletes(Index index, IndexSettings indexSettings, Time`
`970`	`970`	`deleteShardStore("pending delete", shardLock, delete.settings);`
`971`	`971`	`iterator.remove();`
`972`	`972`	`} catch (IOException ex) {`
`973`		`- logger.debug((Supplier<?>) () -> new ParameterizedMessage("{} retry pending delete", shardLock.getShardId()), ex);`
	`973`	`+ logger.debug(() -> new ParameterizedMessage("{} retry pending delete", shardLock.getShardId()), ex);`
`974`	`974`	`}`
`975`	`975`	`} else {`
`976`	`976`	`logger.warn("{} no shard lock for pending delete", delete.shardId);`
Original file line number	Diff line number	Diff line change
`@@ -177,7 +177,7 @@ public void dispatchRequest(RestRequest request, RestChannel channel, ThreadCont`
`177`	`177`	`channel.sendResponse(new BytesRestResponse(channel, e));`
`178`	`178`	`} catch (Exception inner) {`
`179`	`179`	`inner.addSuppressed(e);`
`180`		`- logger.error((Supplier<?>) () ->`
	`180`	`+ logger.error(() ->`
`181`	`181`	`new ParameterizedMessage("failed to send failure response for uri [{}]", request.uri()), inner);`
`182`	`182`	`}`
`183`	`183`	`}`