You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@druid.apache.org by ka...@apache.org on 2023/11/02 06:02:55 UTC
(druid) branch master updated: Better logging in ServiceClientImpl (#15269)
This is an automated email from the ASF dual-hosted git repository.
karan pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/druid.git
The following commit(s) were added to refs/heads/master by this push:
new b82ad59dfe5 Better logging in ServiceClientImpl (#15269)
b82ad59dfe5 is described below
commit b82ad59dfe5acbcef8ae68fe0005b8c446d718ad
Author: Laksh Singla <la...@gmail.com>
AuthorDate: Thu Nov 2 11:32:49 2023 +0530
Better logging in ServiceClientImpl (#15269)
ServiceClientImpl logs the cause of every retry, even though we are retrying the connection attempt. This leads to slight pollution in the logs because a lot of the time, the reason for retrying is the same. This is seen primarily in MSQ, when the worker task hasn't launched yet however controller attempts to connect to the worker task, which can lead to scary-looking messages (with INFO log level), even though they are normal.
This PR changes the logging logic to log every 10 (arbitrary number) retries instead of every retry, to reduce the pollution of the logs.
Note: If there are no retries left, the client returns an exception, which would get thrown up by the caller, and therefore this change doesn't hide any important information.
---
.../msq/indexing/client/IndexerWorkerClient.java | 2 +-
.../org/apache/druid/rpc/ServiceClientImpl.java | 25 ++++++++++++--
.../org/apache/druid/rpc/ServiceRetryPolicy.java | 5 +++
.../org/apache/druid/rpc/StandardRetryPolicy.java | 38 ++++++++++++++++++++--
.../rpc/indexing/SpecificTaskRetryPolicy.java | 6 ++++
5 files changed, 70 insertions(+), 6 deletions(-)
diff --git a/extensions-core/multi-stage-query/src/main/java/org/apache/druid/msq/indexing/client/IndexerWorkerClient.java b/extensions-core/multi-stage-query/src/main/java/org/apache/druid/msq/indexing/client/IndexerWorkerClient.java
index 33f030bc3be..af089a29600 100644
--- a/extensions-core/multi-stage-query/src/main/java/org/apache/druid/msq/indexing/client/IndexerWorkerClient.java
+++ b/extensions-core/multi-stage-query/src/main/java/org/apache/druid/msq/indexing/client/IndexerWorkerClient.java
@@ -301,7 +301,7 @@ public class IndexerWorkerClient implements WorkerClient
final ServiceClient client = clientFactory.makeClient(
id,
locator,
- new SpecificTaskRetryPolicy(workerTaskId, StandardRetryPolicy.unlimited())
+ new SpecificTaskRetryPolicy(workerTaskId, StandardRetryPolicy.unlimitedWithoutRetryLogging())
);
return Pair.of(client, locator);
}
diff --git a/server/src/main/java/org/apache/druid/rpc/ServiceClientImpl.java b/server/src/main/java/org/apache/druid/rpc/ServiceClientImpl.java
index 2146ed5d5be..3178360016a 100644
--- a/server/src/main/java/org/apache/druid/rpc/ServiceClientImpl.java
+++ b/server/src/main/java/org/apache/druid/rpc/ServiceClientImpl.java
@@ -220,7 +220,20 @@ public class ServiceClientImpl implements ServiceClient
if (shouldTry(nextAttemptNumber) && retryPolicy.retryThrowable(t)) {
final long backoffMs = computeBackoffMs(retryPolicy, attemptNumber);
- log.noStackTrace().info(t, buildErrorMessage(request, null, backoffMs, nextAttemptNumber));
+ if (retryPolicy.retryLoggable()) {
+ // log as INFO level if the retry is loggable
+ log.noStackTrace().info(t, buildErrorMessage(request, null, backoffMs, nextAttemptNumber));
+ } else if (log.isDebugEnabled()) {
+ // log as DEBUG level if the debug log is enabled
+ log.noStackTrace().debug(t, buildErrorMessage(request, null, backoffMs, nextAttemptNumber));
+ } else {
+ // If none of the above is valid, we log the error message every tenth time we retry. It seems like
+ // a good balance between making the logs not too verbose when the retry is due to the same cause
+ // and enriching logs with useful information, if we keep retrying due to the same reason
+ if (nextAttemptNumber > 0 && nextAttemptNumber % 10 == 0) {
+ log.noStackTrace().info(t, buildErrorMessage(request, null, backoffMs, nextAttemptNumber));
+ }
+ }
connectExec.schedule(
() -> tryRequest(requestBuilder, handler, retVal, nextAttemptNumber, ImmutableSet.of()),
@@ -272,7 +285,15 @@ public class ServiceClientImpl implements ServiceClient
// Retryable server response (or null errorHolder, which means null result, which can happen
// if the HttpClient encounters an exception in the midst of response processing).
final long backoffMs = computeBackoffMs(retryPolicy, attemptNumber);
- log.info(buildErrorMessage(request, errorHolder, backoffMs, nextAttemptNumber));
+ if (retryPolicy.retryLoggable()) {
+ log.noStackTrace().info(buildErrorMessage(request, errorHolder, backoffMs, nextAttemptNumber));
+ } else if (log.isDebugEnabled()) {
+ log.noStackTrace().debug(buildErrorMessage(request, errorHolder, backoffMs, nextAttemptNumber));
+ } else {
+ if (nextAttemptNumber > 0 && nextAttemptNumber % 10 == 0) {
+ log.noStackTrace().info(buildErrorMessage(request, errorHolder, backoffMs, nextAttemptNumber));
+ }
+ }
connectExec.schedule(
() -> tryRequest(requestBuilder, handler, retVal, nextAttemptNumber, ImmutableSet.of()),
backoffMs,
diff --git a/server/src/main/java/org/apache/druid/rpc/ServiceRetryPolicy.java b/server/src/main/java/org/apache/druid/rpc/ServiceRetryPolicy.java
index 297f369688a..91689523a20 100644
--- a/server/src/main/java/org/apache/druid/rpc/ServiceRetryPolicy.java
+++ b/server/src/main/java/org/apache/druid/rpc/ServiceRetryPolicy.java
@@ -54,6 +54,11 @@ public interface ServiceRetryPolicy
*/
boolean retryThrowable(Throwable t);
+ /**
+ * Returns whether to log the cause of failure before retrying
+ */
+ boolean retryLoggable();
+
/**
* Returns whether service-not-available, i.e. empty {@link ServiceLocations#getLocations()}, can be retried.
*/
diff --git a/server/src/main/java/org/apache/druid/rpc/StandardRetryPolicy.java b/server/src/main/java/org/apache/druid/rpc/StandardRetryPolicy.java
index ceb2a41c807..71097ef6d89 100644
--- a/server/src/main/java/org/apache/druid/rpc/StandardRetryPolicy.java
+++ b/server/src/main/java/org/apache/druid/rpc/StandardRetryPolicy.java
@@ -44,6 +44,9 @@ public class StandardRetryPolicy implements ServiceRetryPolicy
private static final int MAX_ATTEMPTS_ABOUT_AN_HOUR = 125;
private static final StandardRetryPolicy DEFAULT_UNLIMITED_POLICY = new Builder().maxAttempts(UNLIMITED).build();
+ private static final StandardRetryPolicy DEFAULT_UNLIMITED_POLICY_NO_RETRY_LOG = new Builder().maxAttempts(UNLIMITED)
+ .retryLoggable(false)
+ .build();
private static final StandardRetryPolicy DEFAULT_ABOUT_AN_HOUR_POLICY =
new Builder().maxAttempts(MAX_ATTEMPTS_ABOUT_AN_HOUR).build();
private static final StandardRetryPolicy DEFAULT_NO_RETRIES_POLICY = new Builder().maxAttempts(1).build();
@@ -52,13 +55,21 @@ public class StandardRetryPolicy implements ServiceRetryPolicy
private final long minWaitMillis;
private final long maxWaitMillis;
private final boolean retryNotAvailable;
-
- private StandardRetryPolicy(long maxAttempts, long minWaitMillis, long maxWaitMillis, boolean retryNotAvailable)
+ private final boolean retryLoggable;
+
+ private StandardRetryPolicy(
+ long maxAttempts,
+ long minWaitMillis,
+ long maxWaitMillis,
+ boolean retryNotAvailable,
+ boolean retryLoggable
+ )
{
this.maxAttempts = maxAttempts;
this.minWaitMillis = minWaitMillis;
this.maxWaitMillis = maxWaitMillis;
this.retryNotAvailable = retryNotAvailable;
+ this.retryLoggable = retryLoggable;
if (maxAttempts == 0) {
throw new IAE("maxAttempts must be positive (limited) or negative (unlimited); cannot be zero.");
@@ -79,6 +90,14 @@ public class StandardRetryPolicy implements ServiceRetryPolicy
return DEFAULT_UNLIMITED_POLICY;
}
+ /**
+ * Standard unlimited retry policy along with muted the logging for the retries.
+ */
+ public static StandardRetryPolicy unlimitedWithoutRetryLogging()
+ {
+ return DEFAULT_UNLIMITED_POLICY_NO_RETRY_LOG;
+ }
+
/**
* Retry policy that uses up to about an hour of total wait time. Note that this is just the total waiting time
* between attempts. It does not include the time that each attempt takes to execute.
@@ -135,6 +154,12 @@ public class StandardRetryPolicy implements ServiceRetryPolicy
|| (t.getCause() != null && retryThrowable(t.getCause()));
}
+ @Override
+ public boolean retryLoggable()
+ {
+ return retryLoggable;
+ }
+
@Override
public boolean retryNotAvailable()
{
@@ -147,6 +172,7 @@ public class StandardRetryPolicy implements ServiceRetryPolicy
private long minWaitMillis = DEFAULT_MIN_WAIT_MS;
private long maxWaitMillis = DEFAULT_MAX_WAIT_MS;
private boolean retryNotAvailable = true;
+ private boolean retryLoggable = true;
public Builder maxAttempts(final long maxAttempts)
{
@@ -172,9 +198,15 @@ public class StandardRetryPolicy implements ServiceRetryPolicy
return this;
}
+ public Builder retryLoggable(final boolean retryLoggable)
+ {
+ this.retryLoggable = retryLoggable;
+ return this;
+ }
+
public StandardRetryPolicy build()
{
- return new StandardRetryPolicy(maxAttempts, minWaitMillis, maxWaitMillis, retryNotAvailable);
+ return new StandardRetryPolicy(maxAttempts, minWaitMillis, maxWaitMillis, retryNotAvailable, retryLoggable);
}
}
}
diff --git a/server/src/main/java/org/apache/druid/rpc/indexing/SpecificTaskRetryPolicy.java b/server/src/main/java/org/apache/druid/rpc/indexing/SpecificTaskRetryPolicy.java
index 2482786c2a7..36d84f2dc4e 100644
--- a/server/src/main/java/org/apache/druid/rpc/indexing/SpecificTaskRetryPolicy.java
+++ b/server/src/main/java/org/apache/druid/rpc/indexing/SpecificTaskRetryPolicy.java
@@ -77,6 +77,12 @@ public class SpecificTaskRetryPolicy implements ServiceRetryPolicy
return StandardRetryPolicy.unlimited().retryThrowable(t);
}
+ @Override
+ public boolean retryLoggable()
+ {
+ return baseRetryPolicy.retryLoggable();
+ }
+
@Override
public boolean retryNotAvailable()
{
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org