From 8972d6707c88c6de8211b01cbe47a2b52c957d25 Mon Sep 17 00:00:00 2001 From: garyschulte Date: Tue, 30 Jan 2024 12:42:31 -0800 Subject: [PATCH] info level log for pipeline abort (#6459) * info level log for pipeline abort * add depth protection Signed-off-by: garyschulte --- .../besu/ethereum/util/LogUtil.java | 39 ------ .../eth/sync/fastsync/SyncTargetManager.java | 2 +- .../besu/services/pipeline/Pipeline.java | 5 +- .../hyperledger/besu/util/log/LogUtil.java | 92 +++++++++++++ .../besu/util/log/LogUtilTest.java | 127 ++++++++++++++++++ 5 files changed, 224 insertions(+), 41 deletions(-) delete mode 100644 ethereum/core/src/main/java/org/hyperledger/besu/ethereum/util/LogUtil.java create mode 100644 util/src/main/java/org/hyperledger/besu/util/log/LogUtil.java create mode 100644 util/src/test/java/org/hyperledger/besu/util/log/LogUtilTest.java diff --git a/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/util/LogUtil.java b/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/util/LogUtil.java deleted file mode 100644 index 9f1a9a424b..0000000000 --- a/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/util/LogUtil.java +++ /dev/null @@ -1,39 +0,0 @@ -/* - * Copyright Hyperledger Besu Contributors. - * - * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with - * the License. You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on - * an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the - * specific language governing permissions and limitations under the License. - * - * SPDX-License-Identifier: Apache-2.0 - */ -package org.hyperledger.besu.ethereum.util; - -import java.util.concurrent.Executors; -import java.util.concurrent.ScheduledExecutorService; -import java.util.concurrent.TimeUnit; -import java.util.concurrent.atomic.AtomicBoolean; -import java.util.function.Consumer; - -public class LogUtil { - static ScheduledExecutorService executor = Executors.newSingleThreadScheduledExecutor(); - - public static void throttledLog( - final Consumer logger, - final String logMessage, - final AtomicBoolean shouldLog, - final int logRepeatDelay) { - - if (shouldLog.compareAndSet(true, false)) { - logger.accept(logMessage); - - final Runnable runnable = () -> shouldLog.set(true); - executor.schedule(runnable, logRepeatDelay, TimeUnit.SECONDS); - } - } -} diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/fastsync/SyncTargetManager.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/fastsync/SyncTargetManager.java index d0e0a1f0fd..d8bd3f023c 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/fastsync/SyncTargetManager.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/fastsync/SyncTargetManager.java @@ -16,7 +16,7 @@ package org.hyperledger.besu.ethereum.eth.sync.fastsync; import static java.util.concurrent.CompletableFuture.completedFuture; import static org.hyperledger.besu.ethereum.eth.sync.fastsync.PivotBlockRetriever.MAX_QUERY_RETRIES_PER_PEER; -import static org.hyperledger.besu.ethereum.util.LogUtil.throttledLog; +import static org.hyperledger.besu.util.log.LogUtil.throttledLog; import org.hyperledger.besu.ethereum.ProtocolContext; import org.hyperledger.besu.ethereum.core.BlockHeader; diff --git a/services/pipeline/src/main/java/org/hyperledger/besu/services/pipeline/Pipeline.java b/services/pipeline/src/main/java/org/hyperledger/besu/services/pipeline/Pipeline.java index 519e7272f2..7f37a4bac9 100644 --- a/services/pipeline/src/main/java/org/hyperledger/besu/services/pipeline/Pipeline.java +++ b/services/pipeline/src/main/java/org/hyperledger/besu/services/pipeline/Pipeline.java @@ -18,6 +18,7 @@ import static java.util.stream.Collectors.toList; import org.hyperledger.besu.services.pipeline.exception.AsyncOperationException; import org.hyperledger.besu.util.ExceptionUtils; +import org.hyperledger.besu.util.log.LogUtil; import java.util.Collection; import java.util.List; @@ -176,7 +177,9 @@ public class Pipeline { || t instanceof AsyncOperationException) { LOG.trace("Unhandled exception in pipeline. Aborting.", t); } else { - LOG.info("Unexpected exception in pipeline. Aborting."); + LOG.info( + LogUtil.summarizeBesuStackTrace( + "Unexpected exception in pipeline. Aborting.", t)); LOG.debug("Unexpected exception in pipeline. Aborting.", t); } try { diff --git a/util/src/main/java/org/hyperledger/besu/util/log/LogUtil.java b/util/src/main/java/org/hyperledger/besu/util/log/LogUtil.java new file mode 100644 index 0000000000..f626ba4e46 --- /dev/null +++ b/util/src/main/java/org/hyperledger/besu/util/log/LogUtil.java @@ -0,0 +1,92 @@ +/* + * Copyright Hyperledger Besu Contributors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on + * an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the + * specific language governing permissions and limitations under the License. + * + * SPDX-License-Identifier: Apache-2.0 + */ +package org.hyperledger.besu.util.log; + +import java.util.ArrayList; +import java.util.List; +import java.util.concurrent.Executors; +import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicBoolean; +import java.util.function.Consumer; + +/** Utility class for logging. */ +public class LogUtil { + static ScheduledExecutorService executor = Executors.newSingleThreadScheduledExecutor(); + static final String BESU_NAMESPACE = "org.hyperledger.besu"; + static final int MAX_SUMMARY_DEPTH = 20; + + /** + * Throttles logging to a given logger. + * + * @param logger logger as a String consumer + * @param logMessage message to log + * @param shouldLog AtomicBoolean to track whether the message should be logged + * @param logRepeatDelay delay in seconds between repeated logs + */ + public static void throttledLog( + final Consumer logger, + final String logMessage, + final AtomicBoolean shouldLog, + final int logRepeatDelay) { + + if (shouldLog.compareAndSet(true, false)) { + logger.accept(logMessage); + + final Runnable runnable = () -> shouldLog.set(true); + executor.schedule(runnable, logRepeatDelay, TimeUnit.SECONDS); + } + } + + /** + * Summarizes the stack trace of a throwable to the first class in the namespace. Useful for + * limiting exceptionally deep stack traces to the last relevant point in besu code. + * + * @param contextMessage message to prepend to the summary + * @param throwable exception to summarize + * @param namespace namespace to summarize to + * @return summary of the StackTrace + */ + public static String summarizeStackTrace( + final String contextMessage, final Throwable throwable, final String namespace) { + StackTraceElement[] stackTraceElements = throwable.getStackTrace(); + + List stackTraceSummary = new ArrayList<>(); + int depth = 0; + for (StackTraceElement element : stackTraceElements) { + stackTraceSummary.add(String.format("\tat: %s", element)); + if (element.getClassName().startsWith(namespace) || ++depth >= MAX_SUMMARY_DEPTH) { + break; + } + } + + return String.format( + "%s\nThrowable summary: %s\n%s", + contextMessage, throwable, String.join("\n", stackTraceSummary)); + } + + /** + * Summarizes the stack trace of a throwable to the first besu class in the namespace. Useful for + * limiting exceptionally deep stack traces to the last relevant point in besu code. + * + * @param contextMessage message to prepend to the summary + * @param throwable exception to summarize + * @return summary of the StackTrace + */ + public static String summarizeBesuStackTrace( + final String contextMessage, final Throwable throwable) { + return summarizeStackTrace(contextMessage, throwable, BESU_NAMESPACE); + } +} diff --git a/util/src/test/java/org/hyperledger/besu/util/log/LogUtilTest.java b/util/src/test/java/org/hyperledger/besu/util/log/LogUtilTest.java new file mode 100644 index 0000000000..10fef96628 --- /dev/null +++ b/util/src/test/java/org/hyperledger/besu/util/log/LogUtilTest.java @@ -0,0 +1,127 @@ +/* + * Copyright Hyperledger Besu Contributors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on + * an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the + * specific language governing permissions and limitations under the License. + * + * SPDX-License-Identifier: Apache-2.0 + */ +package org.hyperledger.besu.util.log; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.util.Arrays; +import java.util.List; +import java.util.Optional; +import java.util.function.Supplier; + +import org.junit.jupiter.api.Test; + +public class LogUtilTest { + + static final String exceptionMessage = "test message"; + static final String contextMessage = "context message"; + + @Test + public void testMessageSummarizeStackTrace() { + Throwable throwable = new Throwable(exceptionMessage); + String namespace = "org.hyperledger.besu"; + String result = LogUtil.summarizeStackTrace(contextMessage, throwable, namespace); + var lines = + assertFoundInTrace(result, LogUtil.BESU_NAMESPACE, contextMessage, exceptionMessage, 1); + assertThat(lines.size()).isEqualTo(3); + } + + @Test + public void testSummarizeStackTraceToArbitrary() { + Throwable throwable = new Throwable("test message"); + String namespace = "java.lang"; + String result = LogUtil.summarizeStackTrace(contextMessage, throwable, namespace); + var lines = assertFoundInTrace(result, namespace, contextMessage, exceptionMessage, 1); + assertThat(lines.size()).isGreaterThan(3); + } + + @Test + public void testSummarizeLambdaStackTrace() { + String result = ""; + try { + Supplier lambda = () -> besuStackHelper(null); + assertThat(lambda.get()).isNotNull(); + } catch (Exception e) { + String namespace = "org.hyperledger.besu"; + result = LogUtil.summarizeStackTrace(contextMessage, e, namespace); + } + var lines = + assertFoundInTrace( + result, LogUtil.BESU_NAMESPACE, contextMessage, "NullPointerException", 1); + assertThat(lines).hasSize(5); + } + + @Test + public void assertSummarizeStopsAtFirstBesu() { + String result = ""; + try { + Supplier lambda = () -> besuStackHelper((null)); + Supplier lambda2 = lambda::get; + assertThat(lambda2.get()).isNotNull(); + } catch (Exception e) { + result = LogUtil.summarizeBesuStackTrace("besuSummary", e); + } + var lines = + assertFoundInTrace( + result, LogUtil.BESU_NAMESPACE, "besuSummary", "NullPointerException", 1); + assertThat(lines).hasSize(5); + assertThat(lines.get(0)).contains("besuSummary"); + } + + @Test + public void assertMaxDepth() { + String result = ""; + try { + recurseTimesAndThrow(30); + } catch (Exception ex) { + result = LogUtil.summarizeStackTrace("besuSummary", ex, "java.lang"); + } + System.out.println(result); + List lines = Arrays.asList(result.split("\n")); + assertThat(lines).hasSize(22); + assertThat(lines.get(0)).contains("besuSummary"); + } + + private List assertFoundInTrace( + final String result, + final String namespace, + final String ctxMessage, + final String excMessage, + final int times) { + System.out.println(result); + assertThat(result).containsOnlyOnce(ctxMessage); + assertThat(result).containsOnlyOnce(excMessage); + + List lines = Arrays.asList(result.split("\n")); + assertThat( + lines.stream() + .filter(s -> s.contains("at: ")) + .filter(s -> s.contains(namespace)) + .count()) + .isEqualTo(times); + return lines; + } + + private void recurseTimesAndThrow(final int times) { + if (times < 1) { + throw new RuntimeException("FakeStackOverflowError"); + } + recurseTimesAndThrow(times - 1); + } + + private Optional besuStackHelper(final Object o) { + return Optional.of(o); + } +}