diff --git a/bookkeeper-common-allocator/src/main/java/org/apache/bookkeeper/common/allocator/LeakDetectionPolicy.java b/bookkeeper-common-allocator/src/main/java/org/apache/bookkeeper/common/allocator/LeakDetectionPolicy.java index 90d19a4aeef..876220f5db1 100644 --- a/bookkeeper-common-allocator/src/main/java/org/apache/bookkeeper/common/allocator/LeakDetectionPolicy.java +++ b/bookkeeper-common-allocator/src/main/java/org/apache/bookkeeper/common/allocator/LeakDetectionPolicy.java @@ -17,12 +17,12 @@ */ package org.apache.bookkeeper.common.allocator; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; /** * Define the policy for the Netty leak detector. */ -@Slf4j +@CustomLog public enum LeakDetectionPolicy { /** @@ -55,8 +55,10 @@ public static LeakDetectionPolicy parseLevel(String levelStr) { return policy; } } - log.warn("Parse leak detection policy level {} failed. Use the default level: {}", levelStr, - LeakDetectionPolicy.Disabled.name()); + log.warn() + .attr("levelStr", levelStr) + .attr("defaultLevel", LeakDetectionPolicy.Disabled.name()) + .log("Parse leak detection policy level failed. Using the default level"); return LeakDetectionPolicy.Disabled; } } diff --git a/bookkeeper-common-allocator/src/main/java/org/apache/bookkeeper/common/util/ShutdownUtil.java b/bookkeeper-common-allocator/src/main/java/org/apache/bookkeeper/common/util/ShutdownUtil.java index a398b57fe74..fb09bdf0388 100644 --- a/bookkeeper-common-allocator/src/main/java/org/apache/bookkeeper/common/util/ShutdownUtil.java +++ b/bookkeeper-common-allocator/src/main/java/org/apache/bookkeeper/common/util/ShutdownUtil.java @@ -20,12 +20,12 @@ import java.lang.reflect.InvocationTargetException; import java.lang.reflect.Method; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; /** * Forked from Pulsar. */ -@Slf4j +@CustomLog public class ShutdownUtil { private static final Method log4j2ShutdownMethod; @@ -37,7 +37,7 @@ public class ShutdownUtil { .getMethod("shutdown"); } catch (ClassNotFoundException | NoSuchMethodException e) { // ignore when Log4j2 isn't found, log at debug level - log.debug("Cannot find org.apache.logging.log4j.LogManager.shutdown method", e); + log.debug().exception(e).log("Cannot find org.apache.logging.log4j.LogManager.shutdown method"); } log4j2ShutdownMethod = shutdownMethod; } @@ -54,8 +54,10 @@ public static void triggerImmediateForcefulShutdown(int status) { public static void triggerImmediateForcefulShutdown(int status, boolean logging) { try { if (status != 0 && logging) { - log.warn("Triggering immediate shutdown of current process with status {}", status, - new Exception("Stacktrace for immediate shutdown")); + log.warn() + .exception(new Exception("Stacktrace for immediate shutdown")) + .attr("status", status) + .log("Triggering immediate shutdown of current process"); } shutdownLogging(); } finally { @@ -70,7 +72,9 @@ private static void shutdownLogging() { // use reflection to call org.apache.logging.log4j.LogManager.shutdown() log4j2ShutdownMethod.invoke(null); } catch (IllegalAccessException | InvocationTargetException e) { - log.error("Unable to call org.apache.logging.log4j.LogManager.shutdown using reflection.", e); + log.error() + .exception(e) + .log("Unable to call org.apache.logging.log4j.LogManager.shutdown using reflection"); } } } diff --git a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/collections/BusyWait.java b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/collections/BusyWait.java index 25017e0162e..f81227df194 100644 --- a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/collections/BusyWait.java +++ b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/collections/BusyWait.java @@ -21,14 +21,14 @@ import java.lang.invoke.MethodHandle; import java.lang.invoke.MethodHandles; import java.lang.invoke.MethodType; +import lombok.CustomLog; import lombok.experimental.UtilityClass; -import lombok.extern.slf4j.Slf4j; /** * Utility class to use "Thread.onSpinWait()" when available. */ @UtilityClass -@Slf4j +@CustomLog public class BusyWait { /** @@ -54,9 +54,7 @@ public static void onSpinWait() { handle = MethodHandles.lookup().findStatic(Thread.class, "onSpinWait", MethodType.methodType(void.class)); } catch (Throwable t) { // Ignore - if (log.isDebugEnabled()) { - log.debug("Unable to use 'onSpinWait' from JVM", t); - } + log.debug().exception(t).log("Unable to use 'onSpinWait' from JVM"); } ON_SPIN_WAIT = handle; diff --git a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/component/ComponentInfoPublisher.java b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/component/ComponentInfoPublisher.java index 24b0c99760f..2b5d7da988c 100644 --- a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/component/ComponentInfoPublisher.java +++ b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/component/ComponentInfoPublisher.java @@ -23,14 +23,14 @@ import java.util.Map; import java.util.Objects; import java.util.concurrent.ConcurrentHashMap; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; /** * Allows a component to publish information about * the services it implements, the endpoints it exposes * and other useful information for management tools and client. */ -@Slf4j +@CustomLog public class ComponentInfoPublisher { private final Map properties = new ConcurrentHashMap<>(); @@ -99,9 +99,10 @@ public String toString() { * @param value the value, null values are not allowed. */ public void publishProperty(String key, String value) { - if (log.isDebugEnabled()) { - log.debug("publish {}={}", key, value); - } + log.debug() + .attr("key", key) + .attr("value", value) + .log("publish"); if (startupFinished) { throw new IllegalStateException("Server already started, cannot publish " + key); } @@ -112,9 +113,10 @@ public void publishProperty(String key, String value) { } public void publishEndpoint(EndpointInfo endpoint) { - if (log.isDebugEnabled()) { - log.debug("publishEndpoint {} on {}", endpoint, this); - } + log.debug() + .attr("endpoint", endpoint) + .attr("publisher", this) + .log("publishEndpoint"); EndpointInfo exists = endpoints.put(endpoint.id, endpoint); if (exists != null) { throw new IllegalStateException("An endpoint with id " + endpoint.id diff --git a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/component/ComponentStarter.java b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/component/ComponentStarter.java index b8dfced36d5..8710de6c2c9 100644 --- a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/component/ComponentStarter.java +++ b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/component/ComponentStarter.java @@ -19,13 +19,13 @@ package org.apache.bookkeeper.common.component; import java.util.concurrent.CompletableFuture; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.common.concurrent.FutureUtils; /** * Utils to start components. */ -@Slf4j +@CustomLog public class ComponentStarter { static class ComponentShutdownHook implements Runnable { @@ -41,14 +41,18 @@ static class ComponentShutdownHook implements Runnable { @Override public void run() { - log.info("Closing component {} in shutdown hook.", component.getName()); + log.info().attr("component", component.getName()).log("Closing component in shutdown hook"); try { component.close(); - log.info("Closed component {} in shutdown hook successfully. Exiting.", component.getName()); + log.info() + .attr("component", component.getName()) + .log("Closed component in shutdown hook successfully. Exiting"); FutureUtils.complete(future, null); } catch (Throwable e) { - log.error("Failed to close component {} in shutdown hook gracefully, Exiting anyway", - component.getName(), e); + log.error() + .exception(e) + .attr("component", component.getName()) + .log("Failed to close component in shutdown hook gracefully, Exiting anyway"); future.completeExceptionally(e); } } @@ -72,8 +76,11 @@ public static CompletableFuture startComponent(LifecycleComponent componen // register a component exception handler component.setExceptionHandler((t, e) -> { - log.error("Triggered exceptionHandler of Component: {} because of Exception in Thread: {}", - component.getName(), t, e); + log.error() + .exception(e) + .attr("component", component.getName()) + .attr("thread", t) + .log("Triggered exceptionHandler of Component because of Exception in Thread"); System.err.println(e.getMessage()); // start the shutdown hook when an uncaught exception happen in the lifecycle component. try { @@ -86,9 +93,9 @@ public static CompletableFuture startComponent(LifecycleComponent componen component.publishInfo(new ComponentInfoPublisher()); - log.info("Starting component {}.", component.getName()); + log.info().attr("component", component.getName()).log("Starting component"); component.start(); - log.info("Started component {}.", component.getName()); + log.info().attr("component", component.getName()).log("Started component"); return future; } diff --git a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/component/LifecycleComponentStack.java b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/component/LifecycleComponentStack.java index 5b94e049e7d..40f099a001c 100644 --- a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/component/LifecycleComponentStack.java +++ b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/component/LifecycleComponentStack.java @@ -26,12 +26,12 @@ import com.google.common.collect.Lists; import java.lang.Thread.UncaughtExceptionHandler; import java.util.List; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; /** * A stack of {@link LifecycleComponent}s. */ -@Slf4j +@CustomLog public class LifecycleComponentStack implements LifecycleComponent { public static Builder newBuilder() { @@ -124,9 +124,7 @@ public void removeLifecycleListener(LifecycleListener listener) { @Override public void publishInfo(ComponentInfoPublisher componentInfoPublisher) { components.forEach(component -> { - if (log.isDebugEnabled()) { - log.debug("calling publishInfo on {} ", component); - } + log.debug().attr("component", component).log("calling publishInfo"); component.publishInfo(componentInfoPublisher); }); } @@ -134,9 +132,7 @@ public void publishInfo(ComponentInfoPublisher componentInfoPublisher) { @Override public void start() { components.forEach(component -> { - if (log.isDebugEnabled()) { - log.debug("calling publishInfo on {} ", component); - } + log.debug().attr("component", component).log("calling publishInfo"); component.publishInfo(componentInfoPublisher); }); componentInfoPublisher.startupFinished(); diff --git a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/concurrent/FutureUtils.java b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/concurrent/FutureUtils.java index daba9c41ce5..79208bbeb1b 100644 --- a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/concurrent/FutureUtils.java +++ b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/concurrent/FutureUtils.java @@ -31,8 +31,8 @@ import java.util.function.Function; import java.util.stream.Collectors; import javax.annotation.Nullable; +import lombok.CustomLog; import lombok.SneakyThrows; -import lombok.extern.slf4j.Slf4j; import org.apache.bookkeeper.common.stats.OpStatsListener; import org.apache.bookkeeper.common.util.OrderedScheduler; import org.apache.bookkeeper.stats.OpStatsLogger; @@ -40,7 +40,7 @@ /** * Future related utils. */ -@Slf4j +@CustomLog public final class FutureUtils { private FutureUtils() {} @@ -234,9 +234,7 @@ public void onFailure(final Throwable cause) { @Override public void run() { if (done) { - if (log.isDebugEnabled()) { - log.debug("ListFutureProcessor is interrupted."); - } + log.debug("ListFutureProcessor is interrupted"); return; } if (!itemsIter.hasNext()) { @@ -294,12 +292,12 @@ public static CompletableFuture within(final CompletableFuture promise // schedule a timeout to raise timeout exception final java.util.concurrent.ScheduledFuture task = scheduler.scheduleOrdered(key, () -> { if (!promise.isDone() && promise.completeExceptionally(cause)) { - log.info("Raise exception", cause); + log.info().exception(cause).log("Raise exception"); } }, timeout, unit); // when the promise is satisfied, cancel the timeout task promise.whenComplete((value, throwable) -> { - if (!task.cancel(true) && log.isDebugEnabled()) { + if (!task.cancel(true)) { log.debug("Failed to cancel the timeout task"); } } @@ -336,7 +334,7 @@ public void onSuccess(T value) { @Override public void onFailure(Throwable cause) { if (null != errorMsg) { - log.error(errorMsg, cause); + log.error().exception(cause).log(errorMsg); } promise.complete(null); } diff --git a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/conf/ConfigDef.java b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/conf/ConfigDef.java index 6661e80cf4d..0699e38d1e5 100644 --- a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/conf/ConfigDef.java +++ b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/conf/ConfigDef.java @@ -38,15 +38,15 @@ import java.util.TreeSet; import java.util.stream.Collectors; import java.util.stream.IntStream; +import lombok.CustomLog; import lombok.Getter; -import lombok.extern.slf4j.Slf4j; import org.apache.commons.configuration2.Configuration; import org.apache.commons.lang3.StringUtils; /** * A definition of a configuration instance. */ -@Slf4j +@CustomLog @Getter public class ConfigDef { @@ -160,7 +160,11 @@ public static ConfigDef of(Class configClass) { try { builder.withConfigKey((ConfigKey) field.get(null)); } catch (IllegalAccessException e) { - log.error("Illegal to access {}#{}", configClass.getSimpleName(), field.getName(), e); + log.error() + .exception(e) + .attr("configClass", configClass.getSimpleName()) + .attr("field", field.getName()) + .log("Illegal to access field"); } } } diff --git a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/conf/ConfigKey.java b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/conf/ConfigKey.java index b441ee1686e..47c05eec341 100644 --- a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/conf/ConfigKey.java +++ b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/conf/ConfigKey.java @@ -29,7 +29,6 @@ import lombok.Builder.Default; import lombok.Data; import lombok.experimental.Accessors; -import lombok.extern.slf4j.Slf4j; import org.apache.bookkeeper.common.annotation.InterfaceAudience.Public; import org.apache.bookkeeper.common.conf.validators.NullValidator; import org.apache.bookkeeper.common.util.ReflectionUtils; @@ -43,7 +42,6 @@ @Builder(builderMethodName = "internalBuilder") @Accessors(fluent = true) @Public -@Slf4j public class ConfigKey { public static final Comparator ORDERING = (o1, o2) -> { diff --git a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/conf/validators/ClassValidator.java b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/conf/validators/ClassValidator.java index dcd5f41cbdc..3c5c52b82f8 100644 --- a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/conf/validators/ClassValidator.java +++ b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/conf/validators/ClassValidator.java @@ -19,15 +19,15 @@ package org.apache.bookkeeper.common.conf.validators; +import lombok.CustomLog; import lombok.Data; -import lombok.extern.slf4j.Slf4j; import org.apache.bookkeeper.common.conf.Validator; import org.apache.bookkeeper.common.util.ReflectionUtils; /** * Validator that validates a configuration setting is returning a given type of class. */ -@Slf4j +@CustomLog @Data public class ClassValidator implements Validator { @@ -51,15 +51,22 @@ public boolean validate(String name, Object value) { ReflectionUtils.forName((String) value, interfaceClass); return true; } catch (RuntimeException re) { - log.warn("Setting value of '{}' is not '{}' : {}", - name, interfaceClass.getName(), value, re); + log.warn() + .exception(re) + .attr("name", name) + .attr("interfaceClass", interfaceClass.getName()) + .attr("value", value) + .log("Setting value does not match expected interface"); return false; } } else if (value instanceof Class) { Class cls = (Class) value; if (!interfaceClass.isAssignableFrom(cls)) { - log.warn("Setting value of '{}' is not '{}' : {}", - name, interfaceClass.getName(), cls.getName()); + log.warn() + .attr("name", name) + .attr("interfaceClass", interfaceClass.getName()) + .attr("value", cls.getName()) + .log("Setting value does not match expected interface"); return false; } else { return true; diff --git a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/util/SingleThreadExecutor.java b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/util/SingleThreadExecutor.java index d48d8e3613b..31cb8aef320 100644 --- a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/util/SingleThreadExecutor.java +++ b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/util/SingleThreadExecutor.java @@ -32,8 +32,8 @@ import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicIntegerFieldUpdater; import java.util.concurrent.atomic.LongAdder; +import lombok.CustomLog; import lombok.SneakyThrows; -import lombok.extern.slf4j.Slf4j; import org.apache.bookkeeper.common.collections.GrowableMpScArrayConsumerBlockingQueue; import org.apache.bookkeeper.stats.Gauge; import org.apache.bookkeeper.stats.StatsLogger; @@ -44,7 +44,7 @@ *

Tasks are executed in a safe manner: if there are exceptions they are logged and the executor will * proceed with the next tasks. */ -@Slf4j +@CustomLog public class SingleThreadExecutor extends AbstractExecutorService implements ExecutorService, Runnable { private final BlockingQueue queue; private final Thread runner; @@ -134,7 +134,7 @@ public void run() { // Exit loop when interrupted Thread.currentThread().interrupt(); } catch (Throwable t) { - log.error("Exception in executor: {}", t.getMessage(), t); + log.error().exception(t).log("Exception in executor"); throw t; } finally { state = State.Terminated; @@ -151,7 +151,7 @@ private boolean safeRunTask(Runnable r) { return false; } else { tasksFailed.increment(); - log.error("Error while running task: {}", t.getMessage(), t); + log.error().exception(t).log("Error while running task"); } } finally { decrementPendingTaskCount(1); @@ -289,9 +289,10 @@ private void decrementPendingTaskCount(int count) { } int currentPendingCount = pendingTaskCountUpdater.addAndGet(this, -count); - if (log.isDebugEnabled()) { - log.debug("Released {} task(s), current pending count: {}", count, currentPendingCount); - } + log.debug() + .attr("released", count) + .attr("currentPendingCount", currentPendingCount) + .log("Released tasks"); } private void reject() { diff --git a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/util/SingleThreadSafeScheduledExecutorService.java b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/util/SingleThreadSafeScheduledExecutorService.java index d41f2411d3e..66471102dfa 100644 --- a/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/util/SingleThreadSafeScheduledExecutorService.java +++ b/bookkeeper-common/src/main/java/org/apache/bookkeeper/common/util/SingleThreadSafeScheduledExecutorService.java @@ -23,9 +23,9 @@ import java.util.concurrent.ScheduledThreadPoolExecutor; import java.util.concurrent.ThreadFactory; import java.util.concurrent.TimeUnit; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; -@Slf4j +@CustomLog public class SingleThreadSafeScheduledExecutorService extends ScheduledThreadPoolExecutor implements ScheduledExecutorService { @@ -45,7 +45,10 @@ public void run() { try { task.run(); } catch (Throwable t) { - log.warn("Unexpected throwable from task {}: {}", task.getClass(), t.getMessage(), t); + log.warn() + .exception(t) + .attr("taskClass", task.getClass()) + .log("Unexpected throwable from task"); } } } diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/DataIntegrityCheckImpl.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/DataIntegrityCheckImpl.java index 70c6e23882a..a98aa5055f5 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/DataIntegrityCheckImpl.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/DataIntegrityCheckImpl.java @@ -40,7 +40,7 @@ import java.util.concurrent.atomic.AtomicLong; import java.util.concurrent.atomic.AtomicReference; import java.util.stream.Collectors; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.bookie.BookieException; import org.apache.bookkeeper.bookie.LedgerStorage; import org.apache.bookkeeper.bookie.LedgerStorage.StorageState; @@ -54,7 +54,7 @@ /** * An implementation of the DataIntegrityCheck interface. */ -@Slf4j +@CustomLog public class DataIntegrityCheckImpl implements DataIntegrityCheck { private static final int MAX_INFLIGHT = 300; private static final int MAX_ENTRIES_INFLIGHT = 3000; @@ -95,11 +95,19 @@ public synchronized CompletableFuture runPreBootCheck(String reason) { private CompletableFuture runPreBootSequence(String reason) { String runId = UUID.randomUUID().toString(); - log.info("Event: {}, RunId: {}, Reason: {}", Events.PREBOOT_START, runId, reason); + log.info() + .attr("event", Events.PREBOOT_START) + .attr("runId", runId) + .attr("reason", reason) + .log("Preboot start"); try { this.ledgerStorage.setStorageStateFlag(StorageState.NEEDS_INTEGRITY_CHECK); } catch (IOException ioe) { - log.error("Event: {}, RunId: {}", Events.PREBOOT_ERROR, runId, ioe); + log.error() + .exception(ioe) + .attr("event", Events.PREBOOT_ERROR) + .attr("runId", runId) + .log("Preboot error"); return FutureUtils.exception(ioe); } @@ -116,8 +124,12 @@ private CompletableFuture runPreBootSequence(String reason) { ledgerStorage.setMasterKey(ledgerId, new byte[0]); } } catch (IOException ioe) { - log.error("Event: {}, RunId: {}, LedgerId: {}", - Events.ENSURE_LEDGER_ERROR, runId, ledgerId, ioe); + log.error() + .exception(ioe) + .attr("event", Events.ENSURE_LEDGER_ERROR) + .attr("runId", runId) + .attr("ledgerId", ledgerId) + .log("Ensure ledger error"); return FutureUtils.exception(ioe); } } @@ -125,7 +137,11 @@ private CompletableFuture runPreBootSequence(String reason) { }) .whenComplete((ignore, exception) -> { if (exception != null) { - log.error("Event: {}, runId: {}", Events.PREBOOT_ERROR, runId, exception); + log.error() + .exception(exception) + .attr("event", Events.PREBOOT_ERROR) + .attr("runId", runId) + .log("Preboot error"); promise.completeExceptionally(exception); } else { try { @@ -133,11 +149,18 @@ private CompletableFuture runPreBootSequence(String reason) { updateMetadataCache(ledgersCache); - log.info("Event: {}, runId: {}, processed: {}", - Events.PREBOOT_END, runId, ledgersCache.size()); + log.info() + .attr("event", Events.PREBOOT_END) + .attr("runId", runId) + .attr("processed", ledgersCache.size()) + .log("Preboot end"); promise.complete(null); } catch (Throwable t) { - log.error("Event: {}, runId: {}", Events.PREBOOT_ERROR, runId, t); + log.error() + .exception(t) + .attr("event", Events.PREBOOT_ERROR) + .attr("runId", runId) + .log("Preboot error"); promise.completeExceptionally(t); } } @@ -155,12 +178,18 @@ public boolean needsFullCheck() throws IOException { public CompletableFuture runFullCheck() { String runId = UUID.randomUUID().toString(); - log.info("Event: {}, runId: {}", Events.FULL_CHECK_INIT, runId); + log.info() + .attr("event", Events.FULL_CHECK_INIT) + .attr("runId", runId) + .log("Full check init"); return getCachedOrReadMetadata(runId) .thenCompose( (ledgers) -> { - log.info("Event: {}, runId: {}, ledgerCount: {}", - Events.FULL_CHECK_START, runId, ledgers.size()); + log.info() + .attr("event", Events.FULL_CHECK_START) + .attr("runId", runId) + .attr("ledgerCount", ledgers.size()) + .log("Full check start"); return checkAndRecoverLedgers(ledgers, runId).thenApply((resolved) -> { for (LedgerResult r : resolved) { if (r.isMissing() || r.isOK()) { @@ -175,19 +204,24 @@ public CompletableFuture runFullCheck() { .map(r -> r.getThrowable()).findFirst(); if (firstError.isPresent()) { - log.error("Event: {}, runId: {}, ok: {}" - + ", error: {}, missing: {}, ledgersToRetry: {}", - Events.FULL_CHECK_END, runId, - resolved.stream().filter(r -> r.isOK()).count(), - resolved.stream().filter(r -> r.isError()).count(), - resolved.stream().filter(r -> r.isMissing()).count(), - ledgers.size(), firstError.get()); + log.error() + .exception(firstError.get()) + .attr("event", Events.FULL_CHECK_END) + .attr("runId", runId) + .attr("ok", resolved.stream().filter(r -> r.isOK()).count()) + .attr("error", resolved.stream().filter(r -> r.isError()).count()) + .attr("missing", resolved.stream().filter(r -> r.isMissing()).count()) + .attr("ledgersToRetry", ledgers.size()) + .log("Full check end with errors"); } else { - log.info("Event: {}, runId: {}, ok: {}, error: 0, missing: {}, ledgersToRetry: {}", - Events.FULL_CHECK_END, runId, - resolved.stream().filter(r -> r.isOK()).count(), - resolved.stream().filter(r -> r.isMissing()).count(), - ledgers.size()); + log.info() + .attr("event", Events.FULL_CHECK_END) + .attr("runId", runId) + .attr("ok", resolved.stream().filter(r -> r.isOK()).count()) + .attr("error", 0) + .attr("missing", resolved.stream().filter(r -> r.isMissing()).count()) + .attr("ledgersToRetry", ledgers.size()) + .log("Full check end"); } return ledgers; }); @@ -198,16 +232,26 @@ public CompletableFuture runFullCheck() { try { this.ledgerStorage.flush(); if (ledgers.isEmpty()) { - log.info("Event: {}, runId: {}", Events.CLEAR_INTEGCHECK_FLAG, runId); + log.info() + .attr("event", Events.CLEAR_INTEGCHECK_FLAG) + .attr("runId", runId) + .log("Clearing integrity check flag"); this.ledgerStorage.clearStorageStateFlag( StorageState.NEEDS_INTEGRITY_CHECK); } // not really needed as we are modifying the map in place updateMetadataCache(ledgers); - log.info("Event: {}, runId: {}", Events.FULL_CHECK_COMPLETE, runId); + log.info() + .attr("event", Events.FULL_CHECK_COMPLETE) + .attr("runId", runId) + .log("Full check complete"); promise.complete(null); } catch (IOException ioe) { - log.error("Event: {}, runId: {}", Events.FULL_CHECK_ERROR, runId, ioe); + log.error() + .exception(ioe) + .attr("event", Events.FULL_CHECK_ERROR) + .attr("runId", runId) + .log("Full check error"); promise.completeExceptionally(ioe); } return promise; @@ -221,11 +265,17 @@ void updateMetadataCache(Map ledgers) { CompletableFuture> getCachedOrReadMetadata(String runId) { Map map = ledgersCacheRef.get(); if (map != null) { - log.info("Event: {}, runId: {}, ledgerCount: {}", Events.USE_CACHED_METADATA, runId, - map.size()); + log.info() + .attr("event", Events.USE_CACHED_METADATA) + .attr("runId", runId) + .attr("ledgerCount", map.size()) + .log("Using cached metadata"); return CompletableFuture.completedFuture(map); } else { - log.info("Event: {}, runId: {}", Events.REFRESH_METADATA, runId); + log.info() + .attr("event", Events.REFRESH_METADATA) + .attr("runId", runId) + .log("Refreshing metadata"); MetadataAsyncIterator iter = new MetadataAsyncIterator(scheduler, ledgerManager, MAX_INFLIGHT, ZK_TIMEOUT_S, TimeUnit.SECONDS); Map ledgersCache = @@ -265,8 +315,12 @@ private CompletableFuture processPreBoot(long ledgerId, LedgerMetadata met Map.Entry> lastEnsemble = metadata.getAllEnsembles().lastEntry(); CompletableFuture promise = new CompletableFuture<>(); if (lastEnsemble == null) { - log.error("Event: {}, runId: {}, metadata: {}, ledger: {}", - Events.INVALID_METADATA, runId, metadata, ledgerId); + log.error() + .attr("event", Events.INVALID_METADATA) + .attr("runId", runId) + .attr("metadata", metadata) + .attr("ledgerId", ledgerId) + .log("Invalid metadata"); promise.completeExceptionally( new IllegalStateException( String.format("All metadata must have at least one ensemble, %d does not", ledgerId))); @@ -276,14 +330,23 @@ private CompletableFuture processPreBoot(long ledgerId, LedgerMetadata met if (!metadata.isClosed() && lastEnsemble.getValue().contains(bookieId)) { try { - log.info("Event: {}, runId: {}, metadata: {}, ledger: {}", - Events.MARK_LIMBO, runId, metadata, ledgerId); + log.info() + .attr("event", Events.MARK_LIMBO) + .attr("runId", runId) + .attr("metadata", metadata) + .attr("ledgerId", ledgerId) + .log("Marking ledger as limbo"); ledgerStorage.setLimboState(ledgerId); ledgerStorage.setFenced(ledgerId); promise.complete(null); } catch (IOException ioe) { - log.info("Event: {}, runId: {}, metadata: {}, ledger: {}", - Events.LIMBO_OR_FENCE_ERROR, runId, metadata, ledgerId, ioe); + log.info() + .exception(ioe) + .attr("event", Events.LIMBO_OR_FENCE_ERROR) + .attr("runId", runId) + .attr("metadata", metadata) + .attr("ledgerId", ledgerId) + .log("Limbo or fence error"); promise.completeExceptionally(ioe); } } else { @@ -409,18 +472,30 @@ Maybe recoverLedgerIfInLimbo(long ledgerId, LedgerMetadata origM this.ledgerStorage.setMasterKey(ledgerId, new byte[0]); } if (this.ledgerStorage.hasLimboState(ledgerId)) { - log.info("Event: {}, runId: {}, metadata: {}, ledger: {}", - Events.RECOVER_LIMBO_LEDGER, runId, origMetadata, ledgerId); + log.info() + .attr("event", Events.RECOVER_LIMBO_LEDGER) + .attr("runId", runId) + .attr("metadata", origMetadata) + .attr("ledgerId", ledgerId) + .log("Recovering limbo ledger"); return recoverLedger(ledgerId, runId) .toMaybe() .onErrorResumeNext(t -> { if (t instanceof BKException.BKNoSuchLedgerExistsOnMetadataServerException) { - log.info("Event: {}, runId: {}, metadata: {}, ledger: {}", - Events.RECOVER_LIMBO_LEDGER_MISSING, runId, origMetadata, ledgerId); + log.info() + .attr("event", Events.RECOVER_LIMBO_LEDGER_MISSING) + .attr("runId", runId) + .attr("metadata", origMetadata) + .attr("ledgerId", ledgerId) + .log("Recover limbo ledger missing"); return Maybe.empty(); } else { - log.info("Event: {}, runId: {}, metadata: {}, ledger: {}", - Events.RECOVER_LIMBO_LEDGER_ERROR, runId, origMetadata, ledgerId); + log.info() + .attr("event", Events.RECOVER_LIMBO_LEDGER_ERROR) + .attr("runId", runId) + .attr("metadata", origMetadata) + .attr("ledgerId", ledgerId) + .log("Recover limbo ledger error"); return Maybe.error(t); } }); @@ -441,8 +516,12 @@ Single recoverLedger(long ledgerId, String runId) { LedgerMetadata metadata = handle.getLedgerMetadata(); handle.closeAsync().whenComplete((ignore, exception) -> { if (exception != null) { - log.warn("Event: {}, runId: {}, ledger: {}", - Events.RECOVER_LIMBO_LEDGER_CLOSE_ERROR, runId, ledgerId, exception); + log.warn() + .exception(exception) + .attr("event", Events.RECOVER_LIMBO_LEDGER_CLOSE_ERROR) + .attr("runId", runId) + .attr("ledgerId", ledgerId) + .log("Recover limbo ledger close error"); } }); emitter.onSuccess(metadata); @@ -491,8 +570,12 @@ Single checkAndRecoverLedgerEntries(long ledgerId, LedgerMetadata metadata AtomicInteger count = new AtomicInteger(0); AtomicInteger errorCount = new AtomicInteger(0); AtomicReference firstError = new AtomicReference<>(null); - log.info("Event: {}, runId: {}, metadata: {}, ledger: {}", - Events.LEDGER_CHECK_AND_COPY_START, runId, metadata, ledgerId); + log.info() + .attr("event", Events.LEDGER_CHECK_AND_COPY_START) + .attr("runId", runId) + .attr("metadata", metadata) + .attr("ledgerId", ledgerId) + .log("Ledger check and copy start"); return Flowable.rangeLong(0, lastKnownEntry + 1) .subscribeOn(scheduler, false) .flatMapMaybe((entryId) -> { @@ -509,13 +592,25 @@ Single checkAndRecoverLedgerEntries(long ledgerId, LedgerMetadata metadata .count() // do nothing with result, but gives a single even if empty .doOnTerminate(() -> { if (firstError.get() != null) { - log.warn("Event: {}, runId: {}, metadata: {}, ledger: {}, entries: {}, bytes: {}, errors: {}", - Events.LEDGER_CHECK_AND_COPY_END, runId, - metadata, ledgerId, count.get(), byteCount.get(), firstError.get()); + log.warn() + .exception(firstError.get()) + .attr("event", Events.LEDGER_CHECK_AND_COPY_END) + .attr("runId", runId) + .attr("metadata", metadata) + .attr("ledgerId", ledgerId) + .attr("entries", count.get()) + .attr("bytes", byteCount.get()) + .log("Ledger check and copy end with errors"); } else { - log.info("Event: {}, runId: {}, metadata: {}, ledger: {}, entries: {}, bytes: {}, errors: 0", - Events.LEDGER_CHECK_AND_COPY_END, runId, - metadata, ledgerId, count.get(), byteCount.get()); + log.info() + .attr("event", Events.LEDGER_CHECK_AND_COPY_END) + .attr("runId", runId) + .attr("metadata", metadata) + .attr("ledgerId", ledgerId) + .attr("entries", count.get()) + .attr("bytes", byteCount.get()) + .attr("errors", 0) + .log("Ledger check and copy end"); } }) .map(ignore -> ledgerId); diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/DataIntegrityService.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/DataIntegrityService.java index 3d2c040ae61..66847f8532f 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/DataIntegrityService.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/DataIntegrityService.java @@ -25,7 +25,7 @@ import java.util.concurrent.ScheduledExecutorService; import java.util.concurrent.ScheduledFuture; import java.util.concurrent.TimeUnit; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.common.component.AbstractLifecycleComponent; import org.apache.bookkeeper.server.conf.BookieConfiguration; import org.apache.bookkeeper.stats.StatsLogger; @@ -33,7 +33,7 @@ /** * An abstract lifecycle component that can perform data integrity checking. */ -@Slf4j +@CustomLog public class DataIntegrityService extends AbstractLifecycleComponent { private final DataIntegrityCheck check; private final ScheduledExecutorService scheduler; @@ -48,9 +48,11 @@ public DataIntegrityService(BookieConfiguration conf, new ThreadFactoryBuilder() .setNameFormat("bookie-data-integ-%d") .setUncaughtExceptionHandler( - (t, ex) -> log.error("Event: {}, thread: {}", - Events.DATA_INTEG_SERVICE_UNCAUGHT_ERROR, - t, ex)) + (t, ex) -> log.error() + .exception(ex) + .attr("event", Events.DATA_INTEG_SERVICE_UNCAUGHT_ERROR) + .attr("thread", t) + .log("Uncaught error in data integrity service")) .build()); scheduledFuture = null; } @@ -66,8 +68,11 @@ protected TimeUnit intervalUnit() { @Override protected void doStart() { - log.info("Event: {}, interval: {}, intervalUnit: {}", - Events.DATA_INTEG_SERVICE_START, interval(), intervalUnit()); + log.info() + .attr("event", Events.DATA_INTEG_SERVICE_START) + .attr("interval", interval()) + .attr("intervalUnit", intervalUnit()) + .log("Data integrity service start"); synchronized (this) { scheduledFuture = scheduler.scheduleAtFixedRate(() -> { try { @@ -75,10 +80,16 @@ protected void doStart() { check.runFullCheck().get(); } } catch (InterruptedException ie) { - log.warn("Event: {}", Events.DATA_INTEG_SERVICE_INTERRUPTED, ie); + log.warn() + .exception(ie) + .attr("event", Events.DATA_INTEG_SERVICE_INTERRUPTED) + .log("Data integrity service interrupted"); Thread.currentThread().interrupt(); } catch (Throwable t) { - log.error("Event: {}", Events.DATA_INTEG_SERVICE_ERROR, t); + log.error() + .exception(t) + .attr("event", Events.DATA_INTEG_SERVICE_ERROR) + .log("Data integrity service error"); } }, 0, interval(), intervalUnit()); } @@ -86,7 +97,9 @@ protected void doStart() { @Override protected void doStop() { - log.info("Event: {}", Events.DATA_INTEG_SERVICE_STOP); + log.info() + .attr("event", Events.DATA_INTEG_SERVICE_STOP) + .log("Data integrity service stop"); synchronized (this) { if (scheduledFuture != null) { scheduledFuture.cancel(true); diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/EntryCopierImpl.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/EntryCopierImpl.java index a9768b32f1a..8f0d7893462 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/EntryCopierImpl.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/EntryCopierImpl.java @@ -40,7 +40,7 @@ import java.util.concurrent.TimeUnit; import java.util.stream.Collectors; import java.util.stream.IntStream; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.bookie.LedgerStorage; import org.apache.bookkeeper.client.BKException; import org.apache.bookkeeper.client.api.LedgerMetadata; @@ -52,7 +52,7 @@ * Implementation for the EntryCopier interface. Handles the reading of entries * from peer bookies. */ -@Slf4j +@CustomLog public class EntryCopierImpl implements EntryCopier { private static final long SINBIN_DURATION_MS = TimeUnit.MINUTES.toMillis(1); private final BookieId bookieId; @@ -156,7 +156,10 @@ CompletableFuture fetchEntry(long entryId) { final Map.Entry writeSetsForEntryId = this.writeSets .floorEntry(entryId); if (writeSetsForEntryId == null) { - log.error("writeSets for entryId {} not found, writeSets {}", entryId, writeSets); + log.error() + .attr("entryId", entryId) + .attr("writeSets", writeSets) + .log("writeSets for entryId not found"); throw new IllegalStateException("writeSets for entryId: " + entryId + " not found"); } ImmutableList writeSet = writeSetsForEntryId diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/MetadataAsyncIterator.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/MetadataAsyncIterator.java index f942b6b069d..88d40f26578 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/MetadataAsyncIterator.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/datainteg/MetadataAsyncIterator.java @@ -30,7 +30,7 @@ import java.util.concurrent.ExecutionException; import java.util.concurrent.TimeUnit; import java.util.function.BiFunction; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.client.BKException; import org.apache.bookkeeper.client.api.LedgerMetadata; import org.apache.bookkeeper.meta.LedgerManager; @@ -39,7 +39,7 @@ /** * An rxjava ledger metadata iterator. */ -@Slf4j +@CustomLog public class MetadataAsyncIterator { private final Scheduler scheduler; private final LedgerManager ledgerManager; @@ -107,7 +107,10 @@ private CompletableFuture processOne(long ledgerId, .thenCompose((metadata) -> consumer.apply(ledgerId, metadata)) .exceptionally((e) -> { Throwable realException = unwrap(e); - log.warn("Got exception processing ledger {}", ledgerId, realException); + log.warn() + .exception(realException) + .attr("ledgerId", ledgerId) + .log("Got exception processing ledger"); if (realException instanceof BKException.BKNoSuchLedgerExistsOnMetadataServerException) { return null; } else { diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/DbLedgerStorage.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/DbLedgerStorage.java index 6e9f317cbd5..0f672de085d 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/DbLedgerStorage.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/DbLedgerStorage.java @@ -43,7 +43,7 @@ import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; import java.util.stream.Collectors; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.bookie.BookieException; import org.apache.bookkeeper.bookie.CheckpointSource; import org.apache.bookkeeper.bookie.CheckpointSource.Checkpoint; @@ -77,7 +77,7 @@ /** * Implementation of LedgerStorage that uses RocksDB to keep the indexes for entries stored in EntryLogs. */ -@Slf4j +@CustomLog public class DbLedgerStorage implements LedgerStorage { public static final String WRITE_CACHE_MAX_SIZE_MB = "dbStorage_writeCacheMaxSizeMb"; @@ -159,9 +159,9 @@ public void initialize(ServerConfiguration conf, LedgerManager ledgerManager, Le this.numberOfDirs = ledgerDirsManager.getAllLedgerDirs().size(); log.info("Started Db Ledger Storage"); - log.info(" - Number of directories: {}", numberOfDirs); - log.info(" - Write cache size: {} MB", writeCacheMaxSize / MB); - log.info(" - Read Cache: {} MB", readCacheMaxSize / MB); + log.info().attr("numberOfDirs", numberOfDirs).log(" - Number of directories"); + log.info().attr("writeCacheSizeMb", writeCacheMaxSize / MB).log(" - Write cache size"); + log.info().attr("readCacheSizeMb", readCacheMaxSize / MB).log(" - Read Cache"); if (readCacheMaxSize + writeCacheMaxSize > PlatformDependent.estimateMaxDirectMemory()) { throw new IOException("Read and write cache sizes exceed the configured max direct memory size"); diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/PersistentEntryLogMetadataMap.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/PersistentEntryLogMetadataMap.java index bfb8d0d43fd..7e667a388c2 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/PersistentEntryLogMetadataMap.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/PersistentEntryLogMetadataMap.java @@ -32,7 +32,7 @@ import java.util.Map.Entry; import java.util.concurrent.atomic.AtomicBoolean; import java.util.function.BiConsumer; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.bookie.BookieException.EntryLogMetadataMapException; import org.apache.bookkeeper.bookie.EntryLogMetadata; import org.apache.bookkeeper.bookie.EntryLogMetadata.EntryLogMetadataRecyclable; @@ -45,7 +45,7 @@ * Persistent entryLogMetadata-map that stores entry-loggers metadata into * rocksDB. */ -@Slf4j +@CustomLog public class PersistentEntryLogMetadataMap implements EntryLogMetadataMap { // persistent Rocksdb to store metadata-map private final KeyValueStorage metadataMapDB; @@ -77,11 +77,14 @@ protected DataInputStream initialValue() { }; public PersistentEntryLogMetadataMap(String metadataPath, ServerConfiguration conf) throws IOException { - log.info("Loading persistent entrylog metadata-map from {}/{}", metadataPath, METADATA_CACHE); + log.info() + .attr("metadataPath", metadataPath) + .attr("metadataCache", METADATA_CACHE) + .log("Loading persistent entrylog metadata-map"); File dir = new File(metadataPath); if (!dir.mkdirs() && !dir.exists()) { String err = "Unable to create directory " + dir; - log.error(err); + log.error().attr("directory", dir).log("Unable to create directory"); throw new IOException(err); } metadataMapDB = KeyValueStorageRocksDB.factory.newKeyValueStorage(metadataPath, METADATA_CACHE, @@ -115,7 +118,10 @@ public void put(long entryLogId, EntryLogMetadata entryLogMeta) throws EntryLogM entryLogMeta.serialize(dataos.get()); metadataMapDB.put(key.array, baos.get().toByteArray()); } catch (IllegalStateException | IOException e) { - log.error("Failed to serialize entrylog-metadata, entryLogId {}", entryLogId); + log.error() + .exception(e) + .attr("entryLogId", entryLogId) + .log("Failed to serialize entrylog-metadata"); throw new EntryLogMetadataMapException(e); } } finally { @@ -147,13 +153,13 @@ public void forEach(BiConsumer action) throws EntryLogMe } } } catch (IOException e) { - log.error("Failed to iterate over entry-log metadata map {}", e.getMessage(), e); + log.error().exception(e).log("Failed to iterate over entry-log metadata map"); throw new EntryLogMetadataMapException(e); } finally { try { iterator.close(); } catch (IOException e) { - log.error("Failed to close entry-log metadata-map rocksDB iterator {}", e.getMessage(), e); + log.error().exception(e).log("Failed to close entry-log metadata-map rocksDB iterator"); } } } @@ -179,7 +185,10 @@ public void forKey(long entryLogId, BiConsumer action) t metadata.recycle(); } } catch (IOException e) { - log.error("Failed to get metadata for entryLogId {}: {}", entryLogId, e.getMessage(), e); + log.error() + .exception(e) + .attr("entryLogId", entryLogId) + .log("Failed to get metadata for entryLogId"); throw new EntryLogMetadataMapException(e); } finally { key.recycle(); diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/conf/AbstractConfiguration.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/conf/AbstractConfiguration.java index 19d02fb064f..3e79c5b44f7 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/conf/AbstractConfiguration.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/conf/AbstractConfiguration.java @@ -26,7 +26,6 @@ import java.util.List; import java.util.Map; import javax.net.ssl.SSLEngine; -import lombok.extern.slf4j.Slf4j; import org.apache.bookkeeper.common.allocator.LeakDetectionPolicy; import org.apache.bookkeeper.common.allocator.OutOfMemoryPolicy; import org.apache.bookkeeper.common.allocator.PoolingPolicy; @@ -51,7 +50,6 @@ /** * Abstract configuration. */ -@Slf4j public abstract class AbstractConfiguration extends CompositeConfiguration { diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/discover/ZKRegistrationClient.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/discover/ZKRegistrationClient.java index cca631086b0..f0ff9121c32 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/discover/ZKRegistrationClient.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/discover/ZKRegistrationClient.java @@ -38,8 +38,8 @@ import java.util.function.BiConsumer; import java.util.stream.Collectors; import lombok.AccessLevel; +import lombok.CustomLog; import lombok.Getter; -import lombok.extern.slf4j.Slf4j; import org.apache.bookkeeper.client.BKException; import org.apache.bookkeeper.client.BKException.ZKException; import org.apache.bookkeeper.common.concurrent.FutureUtils; @@ -61,7 +61,7 @@ * ZooKeeper based {@link RegistrationClient}. */ -@Slf4j +@CustomLog public class ZKRegistrationClient implements RegistrationClient { static final int ZK_CONNECT_BACKOFF_MS = 200; @@ -113,7 +113,7 @@ private void scheduleWatchTask(long delayMs) { try { scheduler.schedule(this, delayMs, TimeUnit.MILLISECONDS); } catch (RejectedExecutionException ree) { - log.warn("Failed to schedule watch bookies task", ree); + log.warn().exception(ree).log("Failed to schedule watch bookies task"); } } @@ -240,9 +240,10 @@ public CompletableFuture> getBookieServiceInfo(Book // because it can happen than this method is called inside the main // zookeeper client event loop thread Versioned resultFromCache = bookieServiceInfoCache.get(bookieId); - if (log.isDebugEnabled()) { - log.debug("getBookieServiceInfo {} -> {}", bookieId, resultFromCache); - } + log.debug() + .attr("bookieId", bookieId) + .attr("result", resultFromCache) + .log("getBookieServiceInfo"); if (resultFromCache != null) { return CompletableFuture.completedFuture(resultFromCache); } else { @@ -268,11 +269,14 @@ private CompletableFuture> readBookieServiceInfoAsy BookieServiceInfo bookieServiceInfo = deserializeBookieServiceInfo(bookieId, bytes); Versioned result = new Versioned<>(bookieServiceInfo, new LongVersion(stat.getCversion())); - log.info("Update BookieInfoCache (writable bookie) {} -> {}", bookieId, result.getValue()); + log.info() + .attr("bookieId", bookieId) + .attr("info", result.getValue()) + .log("Update BookieInfoCache (writable bookie)"); bookieServiceInfoCache.put(bookieId, result); promise.complete(result); } catch (IOException ex) { - log.error("Cannot update BookieInfo for ", ex); + log.error().exception(ex).log("Cannot update BookieInfo"); promise.completeExceptionally(KeeperException.create(KeeperException.Code.get(rc), path) .initCause(ex)); return; @@ -286,11 +290,14 @@ private CompletableFuture> readBookieServiceInfoAsy BookieServiceInfo bookieServiceInfo = deserializeBookieServiceInfo(bookieId, bytes2); Versioned result = new Versioned<>(bookieServiceInfo, new LongVersion(stat2.getCversion())); - log.info("Update BookieInfoCache (readonly bookie) {} -> {}", bookieId, result.getValue()); + log.info() + .attr("bookieId", bookieId) + .attr("info", result.getValue()) + .log("Update BookieInfoCache (readonly bookie)"); bookieServiceInfoCache.put(bookieId, result); promise.complete(result); } catch (IOException ex) { - log.error("Cannot update BookieInfo for ", ex); + log.error().exception(ex).log("Cannot update BookieInfo"); promise.completeExceptionally(KeeperException.create(KeeperException.Code.get(rc2), path2) .initCause(ex)); return; @@ -471,7 +478,7 @@ private static BookieId stripBookieIdFromPath(String path) { try { return BookieId.parse(path.substring(slash + 1)); } catch (IllegalArgumentException e) { - log.warn("Cannot decode bookieId from {}", path, e); + log.warn().exception(e).attr("path", path).log("Cannot decode bookieId from path"); } } return null; @@ -481,9 +488,11 @@ private class BookieServiceInfoCacheInvalidationWatcher implements Watcher { @Override public void process(WatchedEvent we) { - if (log.isDebugEnabled()) { - log.debug("zk event {} for {} state {}", we.getType(), we.getPath(), we.getState()); - } + log.debug() + .attr("type", we.getType()) + .attr("path", we.getPath()) + .attr("state", we.getState()) + .log("zk event"); if (we.getState() == KeeperState.Expired) { log.info("zk session expired, invalidating cache"); bookieServiceInfoCache.clear(); @@ -495,17 +504,18 @@ public void process(WatchedEvent we) { } switch (we.getType()) { case NodeDeleted: - log.info("Invalidate cache for {}", bookieId); + log.info().attr("bookieId", bookieId).log("Invalidate cache"); bookieServiceInfoCache.remove(bookieId); break; case NodeDataChanged: - log.info("refresh cache for {}", bookieId); + log.info().attr("bookieId", bookieId).log("refresh cache"); readBookieServiceInfoAsync(bookieId); break; default: - if (log.isDebugEnabled()) { - log.debug("ignore cache event {} for {}", we.getType(), bookieId); - } + log.debug() + .attr("type", we.getType()) + .attr("bookieId", bookieId) + .log("ignore cache event"); break; } } diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/discover/ZKRegistrationManager.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/discover/ZKRegistrationManager.java index 58263614073..80a45c0dd7b 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/discover/ZKRegistrationManager.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/discover/ZKRegistrationManager.java @@ -38,7 +38,7 @@ import java.util.concurrent.TimeUnit; import java.util.function.Function; import java.util.stream.Collectors; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.bookie.BookieException; import org.apache.bookkeeper.bookie.BookieException.BookieIllegalOpException; import org.apache.bookkeeper.bookie.BookieException.CookieExistException; @@ -79,15 +79,15 @@ /** * ZooKeeper Based {@link RegistrationManager}. */ -@Slf4j +@CustomLog public class ZKRegistrationManager implements RegistrationManager { private static final Function EXCEPTION_FUNC = cause -> { if (cause instanceof BKException) { - log.error("Failed to get bookie list : ", cause); + log.error().exception(cause).log("Failed to get bookie list"); return (BKException) cause; } else if (cause instanceof InterruptedException) { - log.error("Interrupted reading bookie list : ", cause); + log.error().exception(cause).log("Interrupted reading bookie list"); return new BKInterruptedException(); } else { return new MetaStoreException(); @@ -191,8 +191,11 @@ public void process(WatchedEvent event) { // if the ephemeral owner isn't current zookeeper client // wait for it to be expired. if (stat.getEphemeralOwner() != zk.getSessionId()) { - log.info("Previous bookie registration znode: {} exists, so waiting zk sessiontimeout:" - + " {} ms for znode deletion", regPath, zkTimeoutMs); + log.info() + .attr("regPath", regPath) + .attr("zkTimeoutMs", zkTimeoutMs) + .log("Previous bookie registration znode exists, " + + "waiting zk session timeout for znode deletion"); // waiting for the previous bookie reg znode deletion if (!prevNodeLatch.await(zkTimeoutMs, TimeUnit.MILLISECONDS)) { throw new NodeExistsException(regPath); @@ -205,12 +208,18 @@ public void process(WatchedEvent event) { return false; } } catch (KeeperException ke) { - log.error("ZK exception checking and wait ephemeral znode {} expired : ", regPath, ke); + log.error() + .exception(ke) + .attr("regPath", regPath) + .log("ZK exception checking and waiting ephemeral znode expired"); throw new IOException("ZK exception checking and wait ephemeral znode " + regPath + " expired", ke); } catch (InterruptedException ie) { Thread.currentThread().interrupt(); - log.error("Interrupted checking and wait ephemeral znode {} expired : ", regPath, ie); + log.error() + .exception(ie) + .attr("regPath", regPath) + .log("Interrupted checking and waiting ephemeral znode expired"); throw new IOException("Interrupted checking and wait ephemeral znode " + regPath + " expired", ie); } @@ -229,9 +238,7 @@ public void registerBookie(BookieId bookieId, boolean readOnly, @VisibleForTesting static byte[] serializeBookieServiceInfo(BookieServiceInfo bookieServiceInfo) { - if (log.isDebugEnabled()) { - log.debug("serialize BookieServiceInfo {}", bookieServiceInfo); - } + log.debug().attr("bookieServiceInfo", bookieServiceInfo).log("serialize BookieServiceInfo"); try (ByteArrayOutputStream os = new ByteArrayOutputStream()) { BookieServiceInfoFormat.Builder builder = BookieServiceInfoFormat.newBuilder(); List bsiEndpoints = bookieServiceInfo.getEndpoints().stream() @@ -253,7 +260,10 @@ static byte[] serializeBookieServiceInfo(BookieServiceInfo bookieServiceInfo) { builder.build().writeTo(os); return os.toByteArray(); } catch (IOException err) { - log.error("Cannot serialize bookieServiceInfo from " + bookieServiceInfo); + log.error() + .exception(err) + .attr("bookieServiceInfo", bookieServiceInfo) + .log("Cannot serialize bookieServiceInfo"); throw new RuntimeException(err); } } @@ -267,14 +277,14 @@ private void doRegisterBookie(String regPath, BookieServiceInfo bookieServiceInf zkRegManagerInitialized = true; } } catch (KeeperException ke) { - log.error("ZK exception registering ephemeral Znode for Bookie!", ke); + log.error().exception(ke).log("ZK exception registering ephemeral Znode for Bookie"); // Throw an IOException back up. This will cause the Bookie // constructor to error out. Alternatively, we could do a System // exit here as this is a fatal error. throw new MetadataStoreException(ke); } catch (InterruptedException ie) { Thread.currentThread().interrupt(); - log.error("Interrupted exception registering ephemeral Znode for Bookie!", ie); + log.error().exception(ie).log("Interrupted exception registering ephemeral Znode for Bookie"); // Throw an IOException back up. This will cause the Bookie // constructor to error out. Alternatively, we could do a System // exit here as this is a fatal error. @@ -304,8 +314,10 @@ private void doRegisterReadOnlyBookie(BookieId bookieId, BookieServiceInfo booki // Clear the current registered node zk.delete(regPath, -1); } catch (KeeperException.NoNodeException nne) { - log.warn("No writable bookie registered node {} when transitioning to readonly", - regPath, nne); + log.warn() + .exception(nne) + .attr("regPath", regPath) + .log("No writable bookie registered node when transitioning to readonly"); } } catch (KeeperException | InterruptedException e) { throw new MetadataStoreException(e); @@ -348,8 +360,9 @@ public void writeCookie(BookieId bookieId, try { zk.create(cookiePath, new byte[0], zkAcls, CreateMode.PERSISTENT); } catch (NodeExistsException nne) { - log.info("More than one bookie tried to create {} at once. Safe to ignore.", - cookiePath); + log.info() + .attr("cookiePath", cookiePath) + .log("More than one bookie tried to create cookiePath at once. Safe to ignore"); } } zk.create(zkPath, cookieData.getValue(), zkAcls, CreateMode.PERSISTENT); @@ -404,7 +417,10 @@ public void removeCookie(BookieId bookieId, Version version) throws BookieExcept throw new MetadataStoreException("Failed to delete cookie for bookie " + bookieId); } - log.info("Removed cookie from {} for bookie {}.", cookiePath, bookieId); + log.info() + .attr("cookiePath", cookiePath) + .attr("bookieId", bookieId) + .log("Removed cookie for bookie"); } @@ -414,8 +430,8 @@ public String getClusterInstanceId() throws BookieException { try { if (zk.exists(ledgersRootPath, null) == null) { log.error("BookKeeper metadata doesn't exist in zookeeper. " - + "Has the cluster been initialized? " - + "Try running bin/bookkeeper shell metaformat"); + + "Has the cluster been initialized? " + + "Try running bin/bookkeeper shell metaformat"); throw new KeeperException.NoNodeException("BookKeeper metadata"); } try { @@ -423,7 +439,7 @@ public String getClusterInstanceId() throws BookieException { + INSTANCEID, false, null); instanceId = new String(data, UTF_8); } catch (KeeperException.NoNodeException e) { - log.info("INSTANCEID not exists in zookeeper. Not considering it for data verification"); + log.info("INSTANCEID does not exist in zookeeper. Not considering it for data verification"); } } catch (KeeperException | InterruptedException e) { throw new MetadataStoreException("Failed to get cluster instance id", e); @@ -457,13 +473,15 @@ public boolean prepareFormat() throws Exception { public boolean initNewCluster() throws Exception { String zkServers = ZKMetadataDriverBase.resolveZkServers(conf); String instanceIdPath = ledgersRootPath + "/" + INSTANCEID; - log.info("Initializing ZooKeeper metadata for new cluster, ZKServers: {} ledger root path: {}", zkServers, - ledgersRootPath); + log.info() + .attr("zkServers", zkServers) + .attr("ledgersRootPath", ledgersRootPath) + .log("Initializing ZooKeeper metadata for new cluster"); boolean ledgerRootExists = null != zk.exists(ledgersRootPath, false); if (ledgerRootExists) { - log.error("Ledger root path: {} already exists", ledgersRootPath); + log.error().attr("ledgersRootPath", ledgersRootPath).log("Ledger root path already exists"); return false; } @@ -493,21 +511,28 @@ public boolean initNewCluster() throws Exception { // creates the new layout and stores in zookeeper AbstractZkLedgerManagerFactory.newLedgerManagerFactory(conf, layoutManager); - log.info("Successfully initiated cluster. ZKServers: {} ledger root path: {} instanceId: {}", zkServers, - ledgersRootPath, instanceId); + log.info() + .attr("zkServers", zkServers) + .attr("ledgersRootPath", ledgersRootPath) + .attr("instanceId", instanceId) + .log("Successfully initiated cluster"); return true; } @Override public boolean nukeExistingCluster() throws Exception { String zkServers = ZKMetadataDriverBase.resolveZkServers(conf); - log.info("Nuking ZooKeeper metadata of existing cluster, ZKServers: {} ledger root path: {}", - zkServers, ledgersRootPath); + log.info() + .attr("zkServers", zkServers) + .attr("ledgersRootPath", ledgersRootPath) + .log("Nuking ZooKeeper metadata of existing cluster"); boolean ledgerRootExists = null != zk.exists(ledgersRootPath, false); if (!ledgerRootExists) { - log.info("There is no existing cluster with ledgersRootPath: {} in ZKServers: {}, " - + "so exiting nuke operation", ledgersRootPath, zkServers); + log.info() + .attr("ledgersRootPath", ledgersRootPath) + .attr("zkServers", zkServers) + .log("There is no existing cluster, exiting nuke operation"); return true; } @@ -552,9 +577,7 @@ public boolean format() throws Exception { ZKUtil.deleteRecursive(zk, ZkLedgerUnderreplicationManager.getBasePath(ledgersRootPath) + BookKeeperConstants.DEFAULT_ZK_LEDGERS_ROOT_PATH); } catch (KeeperException.NoNodeException e) { - if (log.isDebugEnabled()) { - log.debug("underreplicated ledgers root path node not exists in zookeeper to delete"); - } + log.debug("underreplicated ledgers root path node does not exist in zookeeper to delete"); } // Clear underreplicatedledger locks @@ -562,27 +585,21 @@ public boolean format() throws Exception { ZKUtil.deleteRecursive(zk, ZkLedgerUnderreplicationManager.getBasePath(ledgersRootPath) + '/' + BookKeeperConstants.UNDER_REPLICATION_LOCK); } catch (KeeperException.NoNodeException e) { - if (log.isDebugEnabled()) { - log.debug("underreplicatedledger locks node not exists in zookeeper to delete"); - } + log.debug("underreplicatedledger locks node does not exist in zookeeper to delete"); } // Clear the cookies try { ZKUtil.deleteRecursive(zk, cookiePath); } catch (KeeperException.NoNodeException e) { - if (log.isDebugEnabled()) { - log.debug("cookies node not exists in zookeeper to delete"); - } + log.debug("cookies node does not exist in zookeeper to delete"); } // Clear the INSTANCEID try { zk.delete(ledgersRootPath + "/" + BookKeeperConstants.INSTANCEID, -1); } catch (KeeperException.NoNodeException e) { - if (log.isDebugEnabled()) { - log.debug("INSTANCEID not exists in zookeeper to delete"); - } + log.debug("INSTANCEID does not exist in zookeeper to delete"); } // create INSTANCEID @@ -601,12 +618,17 @@ public boolean isBookieRegistered(BookieId bookieId) throws BookieException { try { return ((null != zk.exists(regPath, false)) || (null != zk.exists(readonlyRegPath, false))); } catch (KeeperException e) { - log.error("ZK exception while checking registration ephemeral znodes for BookieId: {}", bookieId, e); + log.error() + .exception(e) + .attr("bookieId", bookieId) + .log("ZK exception while checking registration ephemeral znodes for BookieId"); throw new MetadataStoreException(e); } catch (InterruptedException e) { Thread.currentThread().interrupt(); - log.error("InterruptedException while checking registration ephemeral znodes for BookieId: {}", bookieId, - e); + log.error() + .exception(e) + .attr("bookieId", bookieId) + .log("InterruptedException while checking registration ephemeral znodes for BookieId"); throw new MetadataStoreException(e); } } diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/AbstractZkLedgerManagerFactory.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/AbstractZkLedgerManagerFactory.java index 232761e6321..13a93c84a6a 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/AbstractZkLedgerManagerFactory.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/AbstractZkLedgerManagerFactory.java @@ -24,7 +24,7 @@ import java.net.URI; import java.util.List; import java.util.Objects; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.common.util.ReflectionUtils; import org.apache.bookkeeper.conf.AbstractConfiguration; import org.apache.bookkeeper.meta.LayoutManager.LedgerLayoutExistsException; @@ -38,7 +38,7 @@ * Abstract ledger manager factory based on zookeeper, which provides common * methods such as format and validateAndNukeExistingCluster. */ -@Slf4j +@CustomLog public abstract class AbstractZkLedgerManagerFactory implements LedgerManagerFactory { protected ZooKeeper zk; @@ -87,8 +87,10 @@ public boolean validateAndNukeExistingCluster(AbstractConfiguration conf, Lay for (String ledgersRootPathChildren : ledgersRootPathChildrenList) { if ((!AbstractZkLedgerManager.isSpecialZnode(ledgersRootPathChildren)) && (!zkLedgerManager.isLedgerParentNode(ledgersRootPathChildren))) { - log.error("Found unexpected znode : {} under ledgersRootPath : {} so exiting nuke operation", - ledgersRootPathChildren, zkLedgersRootPath); + log.error() + .attr("znode", ledgersRootPathChildren) + .attr("ledgersRootPath", zkLedgersRootPath) + .log("Found unexpected znode under ledgersRootPath, exiting nuke operation"); return false; } } @@ -102,8 +104,10 @@ public boolean validateAndNukeExistingCluster(AbstractConfiguration conf, Lay if (AbstractZkLedgerManager.isSpecialZnode(ledgersRootPathChildren)) { ZKUtil.deleteRecursive(zk, zkLedgersRootPath + "/" + ledgersRootPathChildren); } else { - log.error("Found unexpected znode : {} under ledgersRootPath : {} so exiting nuke operation", - ledgersRootPathChildren, zkLedgersRootPath); + log.error() + .attr("znode", ledgersRootPathChildren) + .attr("ledgersRootPath", zkLedgersRootPath) + .log("Found unexpected znode under ledgersRootPath, exiting nuke operation"); return false; } } @@ -111,8 +115,10 @@ public boolean validateAndNukeExistingCluster(AbstractConfiguration conf, Lay // finally deleting the ledgers rootpath zk.delete(zkLedgersRootPath, -1); - log.info("Successfully nuked existing cluster, ZKServers: {} ledger root path: {}", - zkServers, zkLedgersRootPath); + log.info() + .attr("zkServers", zkServers) + .attr("ledgersRootPath", zkLedgersRootPath) + .log("Successfully nuked existing cluster"); return true; } @@ -137,7 +143,7 @@ public static LedgerManagerFactory newLedgerManagerFactory( try { metadataServiceUriStr = conf.getMetadataServiceUri(); } catch (ConfigurationException e) { - log.error("Failed to retrieve metadata service uri from configuration", e); + log.error().exception(e).log("Failed to retrieve metadata service uri from configuration"); throw new IOException( "Failed to retrieve metadata service uri from configuration", e); } @@ -149,7 +155,9 @@ public static LedgerManagerFactory newLedgerManagerFactory( try { factoryClass = conf.getLedgerManagerFactoryClass(); } catch (ConfigurationException e) { - log.error("Failed to get ledger manager factory class when using an external zookeeper client", e); + log.error() + .exception(e) + .log("Failed to get ledger manager factory class when using an external zookeeper client"); throw new IOException( "Failed to get ledger manager factory class when using an external zookeeper client", e); } @@ -181,9 +189,7 @@ public static LedgerManagerFactory newLedgerManagerFactory( return lmFactory .initialize(conf, layoutManager, lmFactory.getCurrentVersion()); } - if (log.isDebugEnabled()) { - log.debug("read ledger layout {}", layout); - } + log.debug().attr("layout", layout).log("read ledger layout"); // there is existing layout, we need to look into the layout. // handle pre V2 layout @@ -267,8 +273,10 @@ private static Class attemptToResolveShadedLedge AbstractConfiguration conf, String lmfClassName, Throwable cause) throws IOException { if (conf.isShadedLedgerManagerFactoryClassAllowed()) { String shadedPrefix = conf.getShadedLedgerManagerFactoryClassPrefix(); - log.warn("Failed to instantiate ledger manager factory {}, trying its shaded class {}{}", - lmfClassName, shadedPrefix, lmfClassName); + log.warn() + .attr("lmfClassName", lmfClassName) + .attr("shadedPrefix", shadedPrefix) + .log("Failed to instantiate ledger manager factory, trying its shaded class"); // try shading class try { return resolveShadedLedgerManagerFactory(lmfClassName, shadedPrefix); diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/CleanupLedgerManager.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/CleanupLedgerManager.java index bc4cefe6fc2..f785fe90359 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/CleanupLedgerManager.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/CleanupLedgerManager.java @@ -24,7 +24,6 @@ import java.util.concurrent.CompletableFuture; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.locks.ReentrantReadWriteLock; -import lombok.extern.slf4j.Slf4j; import org.apache.bookkeeper.client.BKException; import org.apache.bookkeeper.client.api.LedgerMetadata; import org.apache.bookkeeper.common.concurrent.FutureUtils; @@ -38,7 +37,6 @@ /** * A ledger manager that cleans up resources upon closing. */ -@Slf4j public class CleanupLedgerManager implements LedgerManager { private class CleanupGenericCallback implements GenericCallback { diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/LedgerLayout.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/LedgerLayout.java index 06b2998d949..314a38e5700 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/LedgerLayout.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/LedgerLayout.java @@ -19,17 +19,17 @@ import java.io.IOException; import java.nio.charset.StandardCharsets; +import lombok.CustomLog; import lombok.EqualsAndHashCode; import lombok.Getter; import lombok.ToString; -import lombok.extern.slf4j.Slf4j; /** * This class encapsulates ledger layout information that is persistently stored * in registration service. It provides parsing and serialization methods of such * information. */ -@Slf4j +@CustomLog @Getter @EqualsAndHashCode @ToString @@ -80,9 +80,7 @@ public byte[] serialize() throws IOException { new StringBuilder().append(layoutFormatVersion).append(lSplitter) .append(managerFactoryClass).append(splitter).append(managerVersion).toString(); - if (log.isDebugEnabled()) { - log.debug("Serialized layout info: {}", s); - } + log.debug().attr("layoutInfo", s).log("Serialized layout info"); return s.getBytes(StandardCharsets.UTF_8); } @@ -97,9 +95,7 @@ public byte[] serialize() throws IOException { */ public static LedgerLayout parseLayout(byte[] bytes) throws IOException { String layout = new String(bytes, StandardCharsets.UTF_8); - if (log.isDebugEnabled()) { - log.debug("Parsing Layout: {}", layout); - } + log.debug().attr("layout", layout).log("Parsing Layout"); String[] lines = layout.split(lSplitter); diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/MetadataDrivers.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/MetadataDrivers.java index 44649b01342..1608de0bf7f 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/MetadataDrivers.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/MetadataDrivers.java @@ -35,10 +35,10 @@ import java.util.concurrent.ScheduledExecutorService; import java.util.function.Function; import lombok.AccessLevel; +import lombok.CustomLog; import lombok.Getter; import lombok.NoArgsConstructor; import lombok.ToString; -import lombok.extern.slf4j.Slf4j; import org.apache.bookkeeper.common.util.ReflectionUtils; import org.apache.bookkeeper.conf.ClientConfiguration; import org.apache.bookkeeper.conf.ServerConfiguration; @@ -54,7 +54,7 @@ * */ @NoArgsConstructor(access = AccessLevel.PRIVATE) -@Slf4j +@CustomLog public final class MetadataDrivers { static final String ZK_CLIENT_DRIVER_CLASS = "org.apache.bookkeeper.meta.zk.ZKMetadataClientDriver"; @@ -128,7 +128,10 @@ private static void loadInitialClientDrivers() { new MetadataClientDriverInfo(driver.getClass()); clientDrivers.put(driver.getScheme().toLowerCase(), driverInfo); } catch (Exception e) { - log.warn("Failed to load metadata client driver {}", driverClsName, e); + log.warn() + .exception(e) + .attr("driverClassName", driverClsName) + .log("Failed to load metadata client driver"); } } } @@ -155,7 +158,10 @@ private static void loadInitialBookieDrivers() { new MetadataBookieDriverInfo(driver.getClass()); bookieDrivers.put(driver.getScheme().toLowerCase(), driverInfo); } catch (Exception e) { - log.warn("Failed to load metadata bookie driver {}", driverClsName, e); + log.warn() + .exception(e) + .attr("driverClassName", driverClsName) + .log("Failed to load metadata bookie driver"); } } } @@ -183,13 +189,9 @@ public static void registerClientDriver(String metadataBackendScheme, MetadataClientDriverInfo newDriverInfo = new MetadataClientDriverInfo(driver); oldDriverInfo = clientDrivers.putIfAbsent(scheme, newDriverInfo); if (null != oldDriverInfo) { - if (log.isDebugEnabled()) { - log.debug("Metadata client driver for {} is already there.", scheme); - } + log.debug().attr("scheme", scheme).log("Metadata client driver is already there"); if (allowOverride) { - if (log.isDebugEnabled()) { - log.debug("Overriding client driver for {}", scheme); - } + log.debug().attr("scheme", scheme).log("Overriding client driver"); clientDrivers.put(scheme, newDriverInfo); } } @@ -218,13 +220,9 @@ public static void registerBookieDriver(String metadataBackendScheme, MetadataBookieDriverInfo newDriverInfo = new MetadataBookieDriverInfo(driver); oldDriverInfo = bookieDrivers.putIfAbsent(scheme, newDriverInfo); if (null != oldDriverInfo) { - if (log.isDebugEnabled()) { - log.debug("Metadata bookie driver for {} is already there.", scheme); - } + log.debug().attr("scheme", scheme).log("Metadata bookie driver is already there"); if (allowOverride) { - if (log.isDebugEnabled()) { - log.debug("Overriding bookie driver for {}", scheme); - } + log.debug().attr("scheme", scheme).log("Overriding bookie driver"); bookieDrivers.put(scheme, newDriverInfo); } } diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/ZkLedgerAuditorManager.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/ZkLedgerAuditorManager.java index e3145c63a43..768b2663cbf 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/ZkLedgerAuditorManager.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/ZkLedgerAuditorManager.java @@ -29,7 +29,7 @@ import java.util.List; import java.util.concurrent.CountDownLatch; import java.util.function.Consumer; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.conf.ServerConfiguration; import org.apache.bookkeeper.meta.zk.ZKMetadataDriverBase; import org.apache.bookkeeper.net.BookieId; @@ -49,7 +49,7 @@ /** * ZK based implementation of LedgerAuditorManager. */ -@Slf4j +@CustomLog public class ZkLedgerAuditorManager implements LedgerAuditorManager { private final ZooKeeper zkc; @@ -182,10 +182,9 @@ public void close() throws Exception { // Ok } catch (InterruptedException ie) { Thread.currentThread().interrupt(); - log.warn("InterruptedException while deleting myVote: " + myVote, - ie); + log.warn().exception(ie).attr("myVote", myVote).log("InterruptedException while deleting myVote"); } catch (KeeperException ke) { - log.error("Exception while deleting myVote:" + myVote, ke); + log.error().exception(ke).attr("myVote", myVote).log("Exception while deleting myVote"); } } } diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/zk/ZKMetadataBookieDriver.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/zk/ZKMetadataBookieDriver.java index 252f4b7c1dd..8a8bfb89b1a 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/zk/ZKMetadataBookieDriver.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/zk/ZKMetadataBookieDriver.java @@ -22,7 +22,6 @@ import com.google.common.annotations.VisibleForTesting; import java.util.Optional; -import lombok.extern.slf4j.Slf4j; import org.apache.bookkeeper.conf.ServerConfiguration; import org.apache.bookkeeper.discover.RegistrationManager; import org.apache.bookkeeper.discover.ZKRegistrationManager; @@ -36,7 +35,6 @@ /** * ZooKeeper based metadata bookie driver. */ -@Slf4j public class ZKMetadataBookieDriver extends ZKMetadataDriverBase implements MetadataBookieDriver { diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/zk/ZKMetadataClientDriver.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/zk/ZKMetadataClientDriver.java index a89dd31f145..127f347b7e9 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/zk/ZKMetadataClientDriver.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/zk/ZKMetadataClientDriver.java @@ -22,7 +22,6 @@ import java.util.Optional; import java.util.concurrent.CompletableFuture; import java.util.concurrent.ScheduledExecutorService; -import lombok.extern.slf4j.Slf4j; import org.apache.bookkeeper.conf.ClientConfiguration; import org.apache.bookkeeper.discover.RegistrationClient; import org.apache.bookkeeper.discover.ZKRegistrationClient; @@ -38,7 +37,6 @@ /** * ZooKeeper based metadata client driver. */ -@Slf4j public class ZKMetadataClientDriver extends ZKMetadataDriverBase implements MetadataClientDriver { diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/zk/ZKMetadataDriverBase.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/zk/ZKMetadataDriverBase.java index 6d8c911e370..af3cc770c91 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/zk/ZKMetadataDriverBase.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/zk/ZKMetadataDriverBase.java @@ -31,10 +31,10 @@ import java.util.List; import java.util.Optional; import java.util.concurrent.CompletableFuture; +import lombok.CustomLog; import lombok.Getter; import lombok.Setter; import lombok.SneakyThrows; -import lombok.extern.slf4j.Slf4j; import org.apache.bookkeeper.conf.AbstractConfiguration; import org.apache.bookkeeper.meta.AbstractZkLedgerManagerFactory; import org.apache.bookkeeper.meta.HierarchicalLedgerManagerFactory; @@ -62,7 +62,7 @@ /** * This is a mixin class for supporting zookeeper based metadata driver. */ -@Slf4j +@CustomLog public class ZKMetadataDriverBase implements AutoCloseable { protected static final String SCHEME = "zk"; @@ -178,8 +178,9 @@ protected void initialize(AbstractConfiguration conf, && optionalCtx.get() instanceof ZooKeeper) { this.ledgersRootPath = conf.getZkLedgersRootPath(); - log.info("Initialize zookeeper metadata driver with external zookeeper client : ledgersRootPath = {}.", - ledgersRootPath); + log.info() + .attr("ledgersRootPath", ledgersRootPath) + .log("Initialize zookeeper metadata driver with external zookeeper client"); // if an external zookeeper is added, use the zookeeper instance this.zk = (ZooKeeper) (optionalCtx.get()); @@ -190,7 +191,7 @@ protected void initialize(AbstractConfiguration conf, try { metadataServiceUriStr = conf.getMetadataServiceUri(); } catch (ConfigurationException e) { - log.error("Failed to retrieve metadata service uri from configuration", e); + log.error().exception(e).log("Failed to retrieve metadata service uri from configuration"); throw new MetadataException( Code.INVALID_METADATA_SERVICE_URI, e); } @@ -209,8 +210,11 @@ protected void initialize(AbstractConfiguration conf, throw new MetadataException( Code.INVALID_METADATA_SERVICE_URI, ex); } - log.info("Initialize zookeeper metadata driver at metadata service uri {} :" - + " zkServers = {}, ledgersRootPath = {}.", metadataServiceUriStr, zkServers, ledgersRootPath); + log.info() + .attr("metadataServiceUri", metadataServiceUriStr) + .attr("zkServers", zkServers) + .attr("ledgersRootPath", ledgersRootPath) + .log("Initialize zookeeper metadata driver at metadata service uri"); try { this.zk = ZooKeeperClient.newBuilder() @@ -219,9 +223,7 @@ protected void initialize(AbstractConfiguration conf, .operationRetryPolicy(zkRetryPolicy) .requestRateLimit(conf.getZkRequestRateLimit()) .watchers(Collections.singleton(watchedEvent -> { - if (log.isDebugEnabled()) { - log.debug("Got ZK session watch event: {}", watchedEvent); - } + log.debug().attr("watchedEvent", watchedEvent).log("Got ZK session watch event"); handleState(watchedEvent.getState()); })) .statsLogger(statsLogger) @@ -240,7 +242,7 @@ protected void initialize(AbstractConfiguration conf, } } } catch (IOException | KeeperException e) { - log.error("Failed to create zookeeper client to {}", zkServers, e); + log.error().exception(e).attr("zkServers", zkServers).log("Failed to create zookeeper client"); MetadataException me = new MetadataException( Code.METADATA_SERVICE_ERROR, "Failed to create zookeeper client to " + zkServers, @@ -302,9 +304,7 @@ public void processResult(int rc, String path, Object ctx, String name) { if (KeeperException.Code.OK.intValue() == rc) { createResult.complete(null); } else if (KeeperException.Code.NODEEXISTS.intValue() == rc) { - if (log.isDebugEnabled()) { - log.debug("health check already disabled!"); - } + log.debug("health check already disabled"); createResult.complete(null); } else { createResult.completeExceptionally(KeeperException.create(KeeperException.Code.get(rc), path)); @@ -324,9 +324,7 @@ public void processResult(int rc, String path, Object ctx) { if (KeeperException.Code.OK.intValue() == rc) { deleteResult.complete(null); } else if (KeeperException.Code.NONODE.intValue() == rc) { - if (log.isDebugEnabled()) { - log.debug("health check already enabled!"); - } + log.debug("health check already enabled"); deleteResult.complete(null); } else { deleteResult.completeExceptionally(KeeperException.create(KeeperException.Code.get(rc), path)); @@ -359,7 +357,7 @@ public void close() { try { lmFactory.close(); } catch (IOException e) { - log.warn("Failed to close zookeeper based ledger manager", e); + log.warn().exception(e).log("Failed to close zookeeper based ledger manager"); } lmFactory = null; } @@ -368,7 +366,7 @@ public void close() { zk.close(ZK_CLIENT_WAIT_FOR_SHUTDOWN_TIMEOUT_MS); } catch (InterruptedException e) { Thread.currentThread().interrupt(); - log.warn("Interrupted on closing zookeeper client", e); + log.warn().exception(e).log("Interrupted on closing zookeeper client"); } zk = null; } diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/server/EmbeddedServer.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/server/EmbeddedServer.java index b2ac638db86..4a957d2dcc6 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/server/EmbeddedServer.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/server/EmbeddedServer.java @@ -45,7 +45,7 @@ import java.util.function.Consumer; import java.util.function.Supplier; import java.util.stream.Collectors; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.bookie.Bookie; import org.apache.bookkeeper.bookie.BookieImpl; import org.apache.bookkeeper.bookie.BookieResources; @@ -192,7 +192,7 @@ public static final Builder builder(BookieConfiguration conf) { return new Builder(conf); } - @Slf4j + @CustomLog public static class Builder { private BookieConfiguration conf; @@ -296,7 +296,9 @@ public EmbeddedServer build() throws Exception { StatsProviderService statsProviderService = new StatsProviderService(conf); statsProvider = statsProviderService.getStatsProvider(); serverBuilder.addComponent(statsProviderService); - log.info("Load lifecycle component : {}", statsProviderService.getName()); + log.info() + .attr("component", statsProviderService.getName()) + .log("Load lifecycle component"); } StatsLogger rootStatsLogger = statsProvider.getStatsLogger(""); @@ -357,7 +359,7 @@ public EmbeddedServer build() throws Exception { } if (uncleanShutdownDetection.lastShutdownWasUnclean()) { log.info("Unclean shutdown detected. " - + "The bookie did not register a graceful shutdown prior to this boot."); + + "The bookie did not register a graceful shutdown prior to this boot"); } // bookie takes ownership of storage, so shuts it down @@ -375,7 +377,10 @@ public EmbeddedServer build() throws Exception { ExecutorService rxExecutor = Executors.newFixedThreadPool( 2, new ThreadFactoryBuilder().setNameFormat("rx-schedule-%d") .setUncaughtExceptionHandler( - (t, ex) -> log.error("Uncaught exception on thread {}", t.getName(), ex)) + (t, ex) -> log.error() + .exception(ex) + .attr("thread", t.getName()) + .log("Uncaught exception on thread")) .build()); Scheduler rxScheduler = Schedulers.from(rxExecutor); serverBuilder.addComponent( @@ -432,7 +437,7 @@ public EmbeddedServer build() throws Exception { new BookieService(conf, bookie, rootStatsLogger, allocatorWithOomHandler, uncleanShutdownDetection); serverBuilder.addComponent(bookieService); - log.info("Load lifecycle component : {}", bookieService.getName()); + log.info().attr("component", bookieService.getName()).log("Load lifecycle component"); if (conf.getServerConf().isLocalScrubEnabled()) { serverBuilder.addComponent( @@ -447,7 +452,7 @@ public EmbeddedServer build() throws Exception { autoRecoveryService = new AutoRecoveryService(conf, rootStatsLogger.scope(REPLICATION_SCOPE)); serverBuilder.addComponent(autoRecoveryService); - log.info("Load lifecycle component : {}", autoRecoveryService.getName()); + log.info().attr("component", autoRecoveryService.getName()).log("Load lifecycle component"); } // 7. build data integrity check service @@ -457,7 +462,7 @@ public EmbeddedServer build() throws Exception { dataIntegrityService = new DataIntegrityService(conf, rootStatsLogger.scope(REPLICATION_SCOPE), integCheck); serverBuilder.addComponent(dataIntegrityService); - log.info("Load lifecycle component : {}", dataIntegrityService.getName()); + log.info().attr("component", dataIntegrityService.getName()).log("Load lifecycle component"); } // 8. build http service @@ -471,7 +476,7 @@ public EmbeddedServer build() throws Exception { .build(); httpService = new HttpService(provider, conf, rootStatsLogger); serverBuilder.addComponent(httpService); - log.info("Load lifecycle component : {}", httpService.getName()); + log.info().attr("component", httpService.getName()).log("Load lifecycle component"); } // 9. build extra services @@ -484,12 +489,14 @@ public EmbeddedServer build() throws Exception { rootStatsLogger); for (ServerLifecycleComponent component : components) { serverBuilder.addComponent(component); - log.info("Load lifecycle component : {}", component.getName()); + log.info().attr("component", component.getName()).log("Load lifecycle component"); } } catch (Exception e) { if (conf.getServerConf().getIgnoreExtraServerComponentsStartupFailures()) { - log.info("Failed to load extra components '{}' - {}. Continuing without those components.", - StringUtils.join(extraComponents), e.getMessage()); + log.info() + .exception(e) + .attr("extraComponents", StringUtils.join(extraComponents)) + .log("Failed to load extra components. Continuing without those components"); } else { throw e; } diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/server/Main.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/server/Main.java index fd0d8ed226d..38f308c40a3 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/server/Main.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/server/Main.java @@ -25,7 +25,7 @@ import java.util.Arrays; import java.util.List; import java.util.concurrent.ExecutionException; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.bookie.BookieImpl; import org.apache.bookkeeper.bookie.ExitCode; import org.apache.bookkeeper.common.component.ComponentStarter; @@ -48,7 +48,7 @@ *

It is a rewritten server using {@link org.apache.bookkeeper.common.component.LifecycleComponent}, * replacing the legacy server {@link org.apache.bookkeeper.proto.BookieServer}. */ -@Slf4j +@CustomLog public class Main { static final Options BK_OPTS = new Options(); static { @@ -93,13 +93,13 @@ private static void loadConfFile(ServerConfiguration conf, String confFile) conf.loadConf(new File(confFile).toURI().toURL()); conf.validate(); } catch (MalformedURLException e) { - log.error("Could not open configuration file: {}", confFile, e); + log.error().exception(e).attr("confFile", confFile).log("Could not open configuration file"); throw new IllegalArgumentException(); } catch (ConfigurationException e) { - log.error("Malformed configuration file: {}", confFile, e); + log.error().exception(e).attr("confFile", confFile).log("Malformed configuration file"); throw new IllegalArgumentException(); } - log.info("Using configuration file {}", confFile); + log.info().attr("confFile", confFile).log("Using configuration file"); } @SuppressWarnings("deprecation") @@ -133,7 +133,7 @@ private static ServerConfiguration parseArgs(String[] args) String sZkLedgersRootPath = "/ledgers"; if (cmdLine.hasOption('m')) { sZkLedgersRootPath = cmdLine.getOptionValue('m'); - log.info("Get cmdline zookeeper ledger path: {}", sZkLedgersRootPath); + log.info().attr("zkLedgersRootPath", sZkLedgersRootPath).log("Get cmdline zookeeper ledger path"); overwriteMetadataServiceUri = true; } @@ -141,7 +141,7 @@ private static ServerConfiguration parseArgs(String[] args) String sZK = conf.getZkServers(); if (cmdLine.hasOption('z')) { sZK = cmdLine.getOptionValue('z'); - log.info("Get cmdline zookeeper instance: {}", sZK); + log.info().attr("zkServers", sZK).log("Get cmdline zookeeper instance"); overwriteMetadataServiceUri = true; } @@ -149,49 +149,49 @@ private static ServerConfiguration parseArgs(String[] args) if (overwriteMetadataServiceUri) { String metadataServiceUri = "zk://" + sZK + sZkLedgersRootPath; conf.setMetadataServiceUri(metadataServiceUri); - log.info("Overwritten service uri to {}", metadataServiceUri); + log.info().attr("metadataServiceUri", metadataServiceUri).log("Overwritten service uri"); } if (cmdLine.hasOption('p')) { String sPort = cmdLine.getOptionValue('p'); - log.info("Get cmdline bookie port: {}", sPort); + log.info().attr("port", sPort).log("Get cmdline bookie port"); conf.setBookiePort(Integer.parseInt(sPort)); } if (cmdLine.hasOption("httpport")) { String sPort = cmdLine.getOptionValue("httpport"); - log.info("Get cmdline http port: {}", sPort); + log.info().attr("port", sPort).log("Get cmdline http port"); Integer iPort = Integer.parseInt(sPort); conf.setHttpServerPort(iPort.intValue()); } if (cmdLine.hasOption('j')) { String sJournalDir = cmdLine.getOptionValue('j'); - log.info("Get cmdline journal dir: {}", sJournalDir); + log.info().attr("journalDir", sJournalDir).log("Get cmdline journal dir"); conf.setJournalDirName(sJournalDir); } if (cmdLine.hasOption('i')) { String[] sIndexDirs = cmdLine.getOptionValues('i'); - log.info("Get cmdline index dirs: "); + log.info("Get cmdline index dirs"); for (String index : sIndexDirs) { - log.info("indexDir : {}", index); + log.info().attr("indexDir", index).log("indexDir"); } conf.setIndexDirName(sIndexDirs); } if (cmdLine.hasOption('l')) { String[] sLedgerDirs = cmdLine.getOptionValues('l'); - log.info("Get cmdline ledger dirs: "); + log.info("Get cmdline ledger dirs"); for (String ledger : sLedgerDirs) { - log.info("ledgerdir : {}", ledger); + log.info().attr("ledgerDir", ledger).log("ledgerDir"); } conf.setLedgerDirNames(sLedgerDirs); } return conf; } catch (ParseException e) { - log.error("Error parsing command line arguments : ", e); + log.error().exception(e).log("Error parsing command line arguments"); throw new IllegalArgumentException(e); } } @@ -221,7 +221,7 @@ static int doMain(String[] args) { try { server = buildBookieServer(new BookieConfiguration(conf)); } catch (Exception e) { - log.error("Failed to build bookie server", e); + log.error().exception(e).log("Failed to build bookie server"); System.err.println(e.getMessage()); return ExitCode.SERVER_EXCEPTION; } @@ -232,10 +232,10 @@ static int doMain(String[] args) { } catch (InterruptedException ie) { Thread.currentThread().interrupt(); // the server is interrupted - log.info("Bookie server is interrupted. Exiting ..."); + log.info("Bookie server is interrupted. Exiting"); System.err.println(ie.getMessage()); } catch (ExecutionException ee) { - log.error("Error in bookie shutdown", ee.getCause()); + log.error().exception(ee.getCause()).log("Error in bookie shutdown"); System.err.println(ee.getMessage()); return ExitCode.SERVER_EXCEPTION; } @@ -248,7 +248,7 @@ private static ServerConfiguration parseCommandLine(String[] args) try { conf = parseArgs(args); } catch (IllegalArgumentException iae) { - log.error("Error parsing command line arguments : ", iae); + log.error().exception(iae).log("Error parsing command line arguments"); System.err.println(iae.getMessage()); printUsage(); throw iae; diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/server/http/BKHttpServiceProvider.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/server/http/BKHttpServiceProvider.java index 823cf486524..e5943da6ffb 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/server/http/BKHttpServiceProvider.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/server/http/BKHttpServiceProvider.java @@ -22,7 +22,7 @@ import java.io.IOException; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.bookie.Bookie; import org.apache.bookkeeper.client.BKException; import org.apache.bookkeeper.client.BookKeeperAdmin; @@ -74,7 +74,7 @@ * which provide bookkeeper services to handle http requests * from different http endpoints. */ -@Slf4j +@CustomLog public class BKHttpServiceProvider implements HttpServiceProvider { private final StatsProvider statsProvider; @@ -112,10 +112,10 @@ public void close() throws IOException { } } catch (InterruptedException ie) { Thread.currentThread().interrupt(); - log.error("Interruption while closing BKHttpServiceProvider", ie); + log.error().exception(ie).log("Interruption while closing BKHttpServiceProvider"); throw new IOException("Interruption while closing BKHttpServiceProvider", ie); } catch (BKException e) { - log.error("Error while closing BKHttpServiceProvider", e); + log.error().exception(e).log("Error while closing BKHttpServiceProvider"); throw new IOException("Error while closing BKHttpServiceProvider", e); } } diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/tools/cli/helpers/ClientCommand.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/tools/cli/helpers/ClientCommand.java index 93bd20d80a7..481dabbf721 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/tools/cli/helpers/ClientCommand.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/tools/cli/helpers/ClientCommand.java @@ -18,7 +18,7 @@ */ package org.apache.bookkeeper.tools.cli.helpers; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.client.api.BookKeeper; import org.apache.bookkeeper.common.net.ServiceURI; import org.apache.bookkeeper.conf.ClientConfiguration; @@ -32,7 +32,7 @@ /** * This is a mixin class for commands that needs a bookkeeper client. */ -@Slf4j +@CustomLog public abstract class ClientCommand extends BKCommand { protected ClientCommand(CliSpec spec) { @@ -66,7 +66,7 @@ protected boolean apply(ClientConfiguration conf, run(bk, cmdFlags); return true; } catch (Exception e) { - log.error("Failed to process command '{}'", name(), e); + log.error().exception(e).attr("command", name()).log("Failed to process command"); return false; } } diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/tools/cli/helpers/DiscoveryCommand.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/tools/cli/helpers/DiscoveryCommand.java index f1a28496908..c1bbf7035e0 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/tools/cli/helpers/DiscoveryCommand.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/tools/cli/helpers/DiscoveryCommand.java @@ -24,7 +24,7 @@ import java.util.concurrent.Executors; import java.util.concurrent.ScheduledExecutorService; import lombok.Cleanup; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.client.api.BookKeeper; import org.apache.bookkeeper.conf.ClientConfiguration; import org.apache.bookkeeper.discover.RegistrationClient; @@ -37,7 +37,7 @@ /** * This is a mixin for commands that talks to discovery service. */ -@Slf4j +@CustomLog public abstract class DiscoveryCommand extends ClientCommand { protected DiscoveryCommand(CliSpec spec) { @@ -60,7 +60,7 @@ protected boolean apply(ClientConfiguration clientConf, DiscoveryFlagsT cmdFlags return true; } } catch (Exception e) { - log.error("Fail to process command '{}'", name(), e); + log.error().exception(e).attr("command", name()).log("Fail to process command"); return false; } } diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/util/IOUtils.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/util/IOUtils.java index 1046e404b36..1f226bcae61 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/util/IOUtils.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/util/IOUtils.java @@ -66,46 +66,6 @@ public static void close(io.github.merlimat.slog.Logger log, java.io.Closeable c } } - /** - * Close the Closeable objects and ignore any {@link IOException} or - * null pointers. Must only be used for cleanup in exception handlers. - * - *

SLF4J overload kept for transition during the slog migration. - * - * @param log - * the log to record problems to at debug level. Can be null. - * @param closeables - * the objects to close - */ - public static void close(org.slf4j.Logger log, java.io.Closeable... closeables) { - for (java.io.Closeable c : closeables) { - close(log, c); - } - } - - /** - * Close the Closeable object and ignore any {@link IOException} or - * null pointers. Must only be used for cleanup in exception handlers. - * - *

SLF4J overload kept for transition during the slog migration. - * - * @param log - * the log to record problems to at debug level. Can be null. - * @param closeable - * the objects to close - */ - public static void close(org.slf4j.Logger log, java.io.Closeable closeable) { - if (closeable != null) { - try { - closeable.close(); - } catch (IOException e) { - if (log != null && log.isDebugEnabled()) { - log.debug("Exception in closing " + closeable, e); - } - } - } - } - /** * Confirm prompt for the console operations. * diff --git a/bookkeeper-server/src/test/java/org/apache/bookkeeper/bookie/BookieInitializationTest.java b/bookkeeper-server/src/test/java/org/apache/bookkeeper/bookie/BookieInitializationTest.java index 320221aaf84..7269265d5a9 100644 --- a/bookkeeper-server/src/test/java/org/apache/bookkeeper/bookie/BookieInitializationTest.java +++ b/bookkeeper-server/src/test/java/org/apache/bookkeeper/bookie/BookieInitializationTest.java @@ -827,7 +827,7 @@ public void testBookieStartException() throws Exception { */ loggerOutput.expect((List logEvents) -> { assertThat(logEvents, - hasItem(hasProperty("message", containsString("Triggered exceptionHandler of Component:")))); + hasItem(hasProperty("message", containsString("Triggered exceptionHandler of Component")))); }); } diff --git a/bookkeeper-server/src/test/java/org/apache/bookkeeper/util/LoggerOutput.java b/bookkeeper-server/src/test/java/org/apache/bookkeeper/util/LoggerOutput.java index b507a16f46b..9d0d3012a6b 100644 --- a/bookkeeper-server/src/test/java/org/apache/bookkeeper/util/LoggerOutput.java +++ b/bookkeeper-server/src/test/java/org/apache/bookkeeper/util/LoggerOutput.java @@ -20,13 +20,14 @@ */ package org.apache.bookkeeper.util; -import static org.mockito.Mockito.atLeastOnce; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.Mockito.doAnswer; import static org.mockito.Mockito.spy; -import static org.mockito.Mockito.verify; import java.util.ArrayList; import java.util.List; import java.util.UUID; +import java.util.concurrent.CopyOnWriteArrayList; import java.util.function.Consumer; import java.util.stream.Collectors; import org.apache.logging.log4j.LogManager; @@ -36,7 +37,6 @@ import org.junit.rules.TestRule; import org.junit.runner.Description; import org.junit.runners.model.Statement; -import org.mockito.ArgumentCaptor; import org.slf4j.Marker; import org.slf4j.event.KeyValuePair; import org.slf4j.event.Level; @@ -48,13 +48,10 @@ public class LoggerOutput implements TestRule { private NullAppender logAppender; - private ArgumentCaptor logEventCaptor; + private List capturedEvents; private final List>> logEventExpectations = new ArrayList<>(); public void expect(Consumer> expectation) { - if (logEventCaptor == null) { - logEventCaptor = ArgumentCaptor.forClass(LogEvent.class); - } logEventExpectations.add(expectation); } @@ -67,14 +64,24 @@ public void evaluate() throws Throwable { LoggerContext lc = (LoggerContext) LogManager.getContext(false); logAppender = spy(NullAppender.createAppender(UUID.randomUUID().toString())); logAppender.start(); + capturedEvents = new CopyOnWriteArrayList<>(); + // Snapshot each event eagerly via toImmutable(): some logging + // backends (e.g. slog's Log4j2Logger) reuse a thread-local + // MutableLogEvent across calls, so capturing the reference + // alone would have all captured events alias to the last + // emit on each thread. + doAnswer(invocation -> { + LogEvent event = invocation.getArgument(0); + capturedEvents.add(event.toImmutable()); + return null; + }).when(logAppender).append(any(LogEvent.class)); lc.getConfiguration().addAppender(logAppender); lc.getRootLogger().addAppender(lc.getConfiguration().getAppender(logAppender.getName())); lc.updateLoggers(); try { base.evaluate(); if (!logEventExpectations.isEmpty()) { - verify(logAppender, atLeastOnce()).append(logEventCaptor.capture()); - List logEvents = logEventCaptor.getAllValues().stream() + List logEvents = capturedEvents.stream() .map(LoggerOutput::toSlf4j) .collect(Collectors.toList()); for (Consumer> expectation : logEventExpectations) { @@ -85,7 +92,7 @@ public void evaluate() throws Throwable { lc.getRootLogger().removeAppender(lc.getConfiguration().getAppender(logAppender.getName())); lc.updateLoggers(); logEventExpectations.clear(); - logEventCaptor = null; + capturedEvents = null; } } }; diff --git a/circe-checksum/src/main/java/com/scurrilous/circe/checksum/Java9IntHash.java b/circe-checksum/src/main/java/com/scurrilous/circe/checksum/Java9IntHash.java index 2e779a92766..f2d7276ec0c 100644 --- a/circe-checksum/src/main/java/com/scurrilous/circe/checksum/Java9IntHash.java +++ b/circe-checksum/src/main/java/com/scurrilous/circe/checksum/Java9IntHash.java @@ -22,9 +22,9 @@ import io.netty.util.concurrent.FastThreadLocal; import java.lang.reflect.InvocationTargetException; import java.lang.reflect.Method; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; -@Slf4j +@CustomLog public class Java9IntHash implements IntHash { static final boolean HAS_JAVA9_CRC32C; private static final Method UPDATE_BYTES; @@ -54,9 +54,7 @@ protected byte[] initialValue() { hasJava9CRC32C = true; } catch (Exception e) { - if (log.isDebugEnabled()) { - log.debug("Unable to use reflected methods: ", e); - } + log.debug().exception(e).log("Unable to use reflected methods"); updateBytes = null; updateDirectByteBuffer = null; } diff --git a/cpu-affinity/src/main/java/org/apache/bookkeeper/common/util/affinity/impl/CpuAffinityImpl.java b/cpu-affinity/src/main/java/org/apache/bookkeeper/common/util/affinity/impl/CpuAffinityImpl.java index 94c494f9032..ce4da8ec9d2 100644 --- a/cpu-affinity/src/main/java/org/apache/bookkeeper/common/util/affinity/impl/CpuAffinityImpl.java +++ b/cpu-affinity/src/main/java/org/apache/bookkeeper/common/util/affinity/impl/CpuAffinityImpl.java @@ -32,15 +32,15 @@ import java.util.Set; import java.util.SortedSet; import java.util.TreeSet; +import lombok.CustomLog; import lombok.experimental.UtilityClass; -import lombok.extern.slf4j.Slf4j; import org.apache.bookkeeper.common.util.nativelib.NativeUtils; /** * Implementation of CPU Affinity functionality. */ @UtilityClass -@Slf4j +@CustomLog public class CpuAffinityImpl { private static boolean isInitialized = false; @@ -72,7 +72,10 @@ public static synchronized void acquireCore() { int cpu = pickAvailableCpu(); CpuAffinityJni.setAffinity(cpu); - log.info("Thread {} has successfully acquired ownership of cpu {}", Thread.currentThread().getName(), cpu); + log.info() + .attr("thread", Thread.currentThread().getName()) + .attr("cpu", cpu) + .log("Thread has successfully acquired ownership of cpu"); } catch (IOException e) { throw new RuntimeException("Failed to acquire CPU core: " + e.getMessage()); } @@ -93,20 +96,14 @@ private static synchronized int pickAvailableCpu() throws IOException { isolatedProcessors = IsolatedProcessors.get(); } for (int isolatedCpu : isolatedProcessors) { - if (log.isDebugEnabled()) { - log.debug("Checking CPU {}", isolatedCpu); - } + log.debug().attr("cpu", isolatedCpu).log("Checking CPU"); if (acquiredProcessors.contains(isolatedCpu)) { - if (log.isDebugEnabled()) { - log.debug("Ignoring CPU {} since it's already acquired", isolatedCpu); - } + log.debug().attr("cpu", isolatedCpu).log("Ignoring CPU since it's already acquired"); continue; } if (tryAcquireCpu(isolatedCpu)) { - if (log.isDebugEnabled()) { - log.debug("Using CPU {}", isolatedCpu); - } + log.debug().attr("cpu", isolatedCpu).log("Using CPU"); return isolatedCpu; } } @@ -127,9 +124,7 @@ private static boolean tryAcquireCpu(int targetCpu) throws IOException { for (int cpu : cpusToAcquire) { Closeable lock = tryAcquireFileLock(cpu); if (lock == null) { - if (log.isDebugEnabled()) { - log.debug("Failed to acquire lock on CPU {}", cpu); - } + log.debug().attr("cpu", cpu).log("Failed to acquire lock on CPU"); // Failed to acquire one cpu, release the rest that were already locked for (Closeable l : acquiredCpus) { @@ -208,7 +203,7 @@ private static void init() { NativeUtils.loadLibraryFromJar("/lib/libcpu-affinity.so"); isSupported = CpuAffinityJni.isAvailable(); } catch (final Exception | UnsatisfiedLinkError e) { - log.warn("Unable to load CPU affinity library: {}", e.getMessage(), e); + log.warn().exception(e).log("Unable to load CPU affinity library"); isSupported = false; } finally { isInitialized = true; diff --git a/cpu-affinity/src/main/java/org/apache/bookkeeper/common/util/affinity/impl/IsolatedProcessors.java b/cpu-affinity/src/main/java/org/apache/bookkeeper/common/util/affinity/impl/IsolatedProcessors.java index 2d9cd190273..513f6b47ffc 100644 --- a/cpu-affinity/src/main/java/org/apache/bookkeeper/common/util/affinity/impl/IsolatedProcessors.java +++ b/cpu-affinity/src/main/java/org/apache/bookkeeper/common/util/affinity/impl/IsolatedProcessors.java @@ -31,12 +31,12 @@ import java.nio.file.StandardOpenOption; import java.util.SortedSet; import java.util.TreeSet; +import lombok.CustomLog; import lombok.experimental.UtilityClass; -import lombok.extern.slf4j.Slf4j; import org.apache.commons.lang3.StringUtils; @UtilityClass -@Slf4j +@CustomLog class IsolatedProcessors { private static final Charset ENCODING = StandardCharsets.US_ASCII; @@ -93,7 +93,10 @@ private static void changeCpuStatus(int cpu, boolean enable) throws IOException if (currentState != enable) { Files.write(cpuPath, (enable ? "1\n" : "0\n").getBytes(ENCODING), StandardOpenOption.TRUNCATE_EXISTING); - log.info("{} CPU {}", enable ? "Enabled" : "Disabled", cpu); + log.info() + .attr("status", enable ? "Enabled" : "Disabled") + .attr("cpu", cpu) + .log("Changed CPU status"); } } } diff --git a/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/BKStandaloneContainer.java b/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/BKStandaloneContainer.java index 4e32d5f3076..f5e91d71f5a 100644 --- a/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/BKStandaloneContainer.java +++ b/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/BKStandaloneContainer.java @@ -22,13 +22,13 @@ import java.time.Duration; import java.util.Objects; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.testcontainers.containers.wait.strategy.HostPortWaitStrategy; /** * Test Container for Bookies. */ -@Slf4j +@CustomLog public class BKStandaloneContainer> extends ChaosContainer { private static final int ZK_PORT = 2181; @@ -81,7 +81,9 @@ public void start() { }); super.start(); - log.info("Start a standalone bookkeeper cluster at container {}", this.getContainerName()); + log.info() + .attr("container", this.getContainerName()) + .log("Start a standalone bookkeeper cluster at container"); } @Override diff --git a/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/BookieContainer.java b/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/BookieContainer.java index 4ba5c987ba0..e70071ebdf1 100644 --- a/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/BookieContainer.java +++ b/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/BookieContainer.java @@ -24,7 +24,7 @@ import java.net.URI; import java.time.Duration; import java.util.Objects; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.tests.containers.wait.HttpWaitStrategy; import org.apache.bookkeeper.tests.integration.utils.DockerUtils; import org.testcontainers.containers.wait.strategy.HostPortWaitStrategy; @@ -32,7 +32,7 @@ /** * Test Container for Bookies. */ -@Slf4j +@CustomLog public class BookieContainer> extends ChaosContainer { private static final int BOOKIE_PORT = 3181; @@ -107,7 +107,10 @@ public void start() { }); super.start(); - log.info("Started bookie {} at cluster {}", hostname, clusterName); + log.info() + .attr("hostname", hostname) + .attr("cluster", clusterName) + .log("Started bookie at cluster"); } @Override @@ -125,7 +128,10 @@ protected void beforeStop() { @Override public void stop() { super.stop(); - log.info("Stopped bookie {} at cluster {}", hostname, clusterName); + log.info() + .attr("hostname", hostname) + .attr("cluster", clusterName) + .log("Stopped bookie at cluster"); } @Override diff --git a/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/ChaosContainer.java b/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/ChaosContainer.java index 022152d1034..e42addeb5ae 100644 --- a/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/ChaosContainer.java +++ b/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/ChaosContainer.java @@ -26,7 +26,7 @@ import java.util.Objects; import java.util.concurrent.CompletableFuture; import java.util.concurrent.TimeUnit; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.bookkeeper.tests.integration.utils.DockerUtils; import org.apache.commons.lang3.StringUtils; import org.testcontainers.containers.GenericContainer; @@ -34,7 +34,7 @@ /** * A base container provides chaos capability. */ -@Slf4j +@CustomLog public class ChaosContainer> extends GenericContainer { static class LogContainerResultCb extends ResultCallback.Adapter { @@ -100,13 +100,27 @@ public String getContainerLog() { public ExecResult execCmd(String... cmd) throws Exception { String cmdString = StringUtils.join(cmd, " "); - log.info("DOCKER.exec({}:{}): Executing ...", this.getContainerId(), cmdString); + log.info() + .attr("containerId", this.getContainerId()) + .attr("cmd", cmdString) + .log("DOCKER.exec: Executing"); ExecResult result = execInContainer(cmd); - log.info("Docker.exec({}:{}): Done", this.getContainerId(), cmdString); - log.info("Docker.exec({}:{}): Stdout -\n{}", this.getContainerId(), cmdString, result.getStdout()); - log.info("Docker.exec({}:{}): Stderr -\n{}", this.getContainerId(), cmdString, result.getStderr()); + log.info() + .attr("containerId", this.getContainerId()) + .attr("cmd", cmdString) + .log("Docker.exec: Done"); + log.info() + .attr("containerId", this.getContainerId()) + .attr("cmd", cmdString) + .attr("stdout", result.getStdout()) + .log("Docker.exec: Stdout"); + log.info() + .attr("containerId", this.getContainerId()) + .attr("cmd", cmdString) + .attr("stderr", result.getStderr()) + .log("Docker.exec: Stderr"); return result; } diff --git a/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/ZKContainer.java b/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/ZKContainer.java index ba894d2d510..05b6d55582e 100644 --- a/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/ZKContainer.java +++ b/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/ZKContainer.java @@ -21,13 +21,13 @@ import static java.time.temporal.ChronoUnit.SECONDS; import java.time.Duration; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.testcontainers.containers.wait.strategy.HostPortWaitStrategy; /** * Test container that runs zookeeper. */ -@Slf4j +@CustomLog public class ZKContainer> extends MetadataStoreContainer { private static final int ZK_PORT = 2181; @@ -67,8 +67,11 @@ public void start() { this.withCreateContainerCmdModifier(createContainerCmd -> createContainerCmd.withHostName(HOST_NAME)); super.start(); - log.info("Start a zookeeper server at container {} : external service uri = {}, internal service uri = {}", - this.getContainerName(), getExternalServiceUri(), getInternalServiceUri()); + log.info() + .attr("container", this.getContainerName()) + .attr("externalServiceUri", getExternalServiceUri()) + .attr("internalServiceUri", getInternalServiceUri()) + .log("Start a zookeeper server at container"); } } diff --git a/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/wait/HttpWaitStrategy.java b/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/wait/HttpWaitStrategy.java index fbbf7c5e955..2446bd77436 100644 --- a/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/wait/HttpWaitStrategy.java +++ b/tests/integration-tests-topologies/src/main/java/org/apache/bookkeeper/tests/containers/wait/HttpWaitStrategy.java @@ -31,6 +31,7 @@ import java.net.URL; import java.util.concurrent.TimeUnit; import java.util.function.Predicate; +import lombok.CustomLog; import org.rnorth.ducttape.TimeoutException; import org.testcontainers.containers.ContainerLaunchException; import org.testcontainers.containers.wait.strategy.AbstractWaitStrategy; @@ -38,9 +39,8 @@ /** * An wait strategy to wait for http ports. */ +@CustomLog public class HttpWaitStrategy extends AbstractWaitStrategy { - @java.lang.SuppressWarnings("all") - private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(HttpWaitStrategy.class); /** * Authorization HTTP header. */ @@ -129,7 +129,11 @@ protected void waitUntilReady() { final String containerName = waitStrategyTarget.getContainerInfo().getName(); final int livenessCheckPort = waitStrategyTarget.getMappedPort(port); final String uri = buildLivenessUri(livenessCheckPort).toString(); - log.info("{}: Waiting for {} seconds for URL: {}", containerName, startupTimeout.getSeconds(), uri); + log.info() + .attr("container", containerName) + .attr("seconds", startupTimeout.getSeconds()) + .attr("url", uri) + .log("Waiting for URL"); // try to connect to the URL try { retryUntilSuccess((int) startupTimeout.getSeconds(), TimeUnit.SECONDS, () -> { diff --git a/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/BookKeeperClusterUtils.java b/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/BookKeeperClusterUtils.java index ab8062b6b78..fcb9e60a19a 100644 --- a/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/BookKeeperClusterUtils.java +++ b/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/BookKeeperClusterUtils.java @@ -28,17 +28,17 @@ import java.util.concurrent.TimeUnit; import java.util.stream.Collectors; import lombok.Cleanup; +import lombok.CustomLog; import lombok.SneakyThrows; import org.apache.zookeeper.CreateMode; import org.apache.zookeeper.Watcher.Event.KeeperState; import org.apache.zookeeper.ZooDefs.Ids; import org.apache.zookeeper.ZooKeeper; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; /** * Utils for interacting a bookkeeper cluster used for integration tests. */ +@CustomLog public class BookKeeperClusterUtils { public static final String CURRENT_VERSION = System.getProperty("currentVersion"); @@ -63,8 +63,6 @@ public class BookKeeperClusterUtils { public static final List UPGRADE_DOWNGRADE_TEST_VERSIONS = Arrays.asList(VERSION_4_14_x, VERSION_4_15_x, VERSION_4_16_x, VERSION_4_17_x); - private static final Logger LOG = LoggerFactory.getLogger(BookKeeperClusterUtils.class); - public static boolean hasVersionLatestMetadataFormat(String version) { return OLD_CLIENT_VERSIONS_WITH_CURRENT_LEDGER_METADATA_FORMAT.contains(version); } @@ -250,12 +248,14 @@ private static boolean waitBookieState(DockerClient docker, String containerId, timeoutMillis -= pollMillis; } } catch (Exception e) { - LOG.error("Exception checking for bookie state", e); + log.error().exception(e).log("Exception checking for bookie state"); return false; } - LOG.warn("Bookie {} didn't go {} after {} seconds", - containerId, upOrDown ? "up" : "down", - timeoutUnit.toSeconds(timeout)); + log.warn() + .attr("containerId", containerId) + .attr("expectedState", upOrDown ? "up" : "down") + .attr("seconds", timeoutUnit.toSeconds(timeout)) + .log("Bookie did not reach expected state in time"); return false; } @@ -273,7 +273,7 @@ public static boolean startBookieWithVersion(DockerClient docker, String contain try { DockerUtils.runCommand(docker, containerId, "supervisorctl", "start", "bookkeeper-" + version); } catch (Exception e) { - LOG.error("Exception starting bookie", e); + log.error().exception(e).log("Exception starting bookie"); return false; } return waitBookieUp(docker, containerId, 10, TimeUnit.SECONDS); @@ -294,7 +294,7 @@ public static boolean stopBookie(DockerClient docker, String containerId) { try { DockerUtils.runCommand(docker, containerId, "supervisorctl", "stop", "all"); } catch (Exception e) { - LOG.error("Exception stopping bookie", e); + log.error().exception(e).log("Exception stopping bookie"); return false; } return waitBookieDown(docker, containerId, 5, TimeUnit.SECONDS); diff --git a/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/DockerUtils.java b/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/DockerUtils.java index f0dd46912a6..6e6c482c870 100644 --- a/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/DockerUtils.java +++ b/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/DockerUtils.java @@ -40,16 +40,15 @@ import java.util.regex.Pattern; import java.util.stream.Collectors; import java.util.zip.GZIPOutputStream; +import lombok.CustomLog; import org.apache.commons.compress.archivers.tar.TarArchiveEntry; import org.apache.commons.compress.archivers.tar.TarArchiveInputStream; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; /** * Docker utilities for integration tests. */ +@CustomLog public class DockerUtils { - private static final Logger LOG = LoggerFactory.getLogger(DockerUtils.class); private static File getTargetDirectory(String containerId) { String base = System.getProperty("maven.buildDirectory"); @@ -58,7 +57,7 @@ private static File getTargetDirectory(String containerId) { } File directory = new File(base + "/container-logs/" + containerId); if (!directory.exists() && !directory.mkdirs()) { - LOG.error("Error creating directory for container logs."); + log.error("Error creating directory for container logs"); } return directory; } @@ -96,10 +95,13 @@ public void onComplete() { }); future.get(); } catch (RuntimeException | ExecutionException | IOException e) { - LOG.error("Error dumping log for {}", containerId, e); + log.error().exception(e).attr("containerId", containerId).log("Error dumping log"); } catch (InterruptedException ie) { Thread.currentThread().interrupt(); - LOG.info("Interrupted dumping log from container {}", containerId, ie); + log.info() + .exception(ie) + .attr("containerId", containerId) + .log("Interrupted dumping log from container"); } } @@ -123,7 +125,10 @@ public static void dumpContainerDirToTargetCompressed(DockerClient dockerClient, read = dockerStream.read(block, 0, readBlockSize); } } catch (RuntimeException | IOException e) { - LOG.error("Error reading dir from container {}", containerName, e); + log.error() + .exception(e) + .attr("containerName", containerName) + .log("Error reading dir from container"); } } @@ -152,7 +157,10 @@ public static void dumpContainerLogDirToTarget(DockerClient docker, String conta entry = stream.getNextEntry(); } } catch (RuntimeException | IOException e) { - LOG.error("Error reading bk logs from container {}", containerId, e); + log.error() + .exception(e) + .attr("containerId", containerId) + .log("Error reading bk logs from container"); } } @@ -185,12 +193,19 @@ public void close() {} @Override public void onStart(Closeable closeable) { - LOG.info("DOCKER.exec({}:{}): Executing...", containerId, cmdString); + log.info() + .attr("containerId", containerId) + .attr("cmd", cmdString) + .log("DOCKER.exec: Executing"); } @Override public void onNext(Frame object) { - LOG.info("DOCKER.exec({}:{}): {}", containerId, cmdString, object); + log.info() + .attr("containerId", containerId) + .attr("cmd", cmdString) + .attr("frame", object) + .log("DOCKER.exec: frame"); output.append(new String(object.getPayload(), UTF_8)); } @@ -201,7 +216,10 @@ public void onError(Throwable throwable) { @Override public void onComplete() { - LOG.info("DOCKER.exec({}:{}): Done", containerId, cmdString); + log.info() + .attr("containerId", containerId) + .attr("cmd", cmdString) + .log("DOCKER.exec: Done"); future.complete(true); } }); @@ -214,13 +232,22 @@ public void onComplete() { } long retCode = resp.getExitCodeLong(); if (retCode != 0) { - LOG.error("DOCKER.exec({}:{}): failed with {} : {}", containerId, cmdString, retCode, output); + log.error() + .attr("containerId", containerId) + .attr("cmd", cmdString) + .attr("retCode", retCode) + .attr("output", output) + .log("DOCKER.exec: failed"); if (!ignoreError) { throw new Exception(String.format("cmd(%s) failed on %s with exitcode %d", cmdString, containerId, retCode)); } } else { - LOG.info("DOCKER.exec({}:{}): completed with {}", containerId, cmdString, retCode); + log.info() + .attr("containerId", containerId) + .attr("cmd", cmdString) + .attr("retCode", retCode) + .log("DOCKER.exec: completed"); } return output.toString(); } diff --git a/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/MavenClassLoader.java b/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/MavenClassLoader.java index ba533ad7f8b..754a6bffbe4 100644 --- a/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/MavenClassLoader.java +++ b/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/MavenClassLoader.java @@ -48,7 +48,7 @@ import java.util.concurrent.TimeUnit; import java.util.stream.Collectors; import java.util.zip.GZIPInputStream; -import lombok.extern.slf4j.Slf4j; +import lombok.CustomLog; import org.apache.commons.compress.archivers.ArchiveStreamFactory; import org.apache.commons.compress.archivers.tar.TarArchiveEntry; import org.apache.commons.compress.archivers.tar.TarArchiveInputStream; @@ -65,7 +65,7 @@ /** * A maven class loader for resolving and loading maven artifacts. */ -@Slf4j +@CustomLog public class MavenClassLoader implements AutoCloseable { private static ScheduledExecutorService delayedCloseExecutor = createExecutorThatShutsDownIdleThreads(); @@ -337,7 +337,7 @@ public void close() throws Exception { try { ((Closeable) classloader).close(); } catch (Exception e) { - log.error("Failed to close classloader", e); + log.error().exception(e).log("Failed to close classloader"); } }, 5, TimeUnit.SECONDS); } diff --git a/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/ThreadReaper.java b/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/ThreadReaper.java index 5664cdc832e..9a2fe69c49d 100644 --- a/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/ThreadReaper.java +++ b/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/ThreadReaper.java @@ -20,14 +20,13 @@ import java.util.concurrent.Callable; import java.util.concurrent.CompletableFuture; import java.util.concurrent.atomic.AtomicInteger; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; +import lombok.CustomLog; /** * A thread reaper. */ +@CustomLog public class ThreadReaper { - private static final Logger LOG = LoggerFactory.getLogger(ThreadReaper.class); private static AtomicInteger groupId = new AtomicInteger(0); public static T runWithReaper(Callable callable) throws Exception { @@ -47,17 +46,17 @@ public static T runWithReaper(Callable callable) throws Exception { while (tg.activeCount() > 0 && i > 0) { tg.interrupt(); Thread.sleep(100); - LOG.info("{} threads still alive", tg.activeCount()); + log.info().attr("activeCount", tg.activeCount()).log("threads still alive"); i--; } if (tg.activeCount() == 0) { - LOG.info("All threads in reaper group dead"); + log.info("All threads in reaper group dead"); } else { Thread[] threads = new Thread[tg.activeCount()]; int found = tg.enumerate(threads); - LOG.info("Leaked {} threads", found); + log.info().attr("leakedCount", found).log("Leaked threads"); for (int j = 0; j < found; j++) { - LOG.info("Leaked thread {}", threads[j]); + log.info().attr("thread", threads[j]).log("Leaked thread"); } } return ret; diff --git a/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/ZooKeeperAwaitStrategy.java b/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/ZooKeeperAwaitStrategy.java index e8de6d70358..f1507d71638 100644 --- a/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/ZooKeeperAwaitStrategy.java +++ b/tests/integration-tests-utils/src/main/java/org/apache/bookkeeper/tests/integration/utils/ZooKeeperAwaitStrategy.java @@ -17,20 +17,20 @@ */ package org.apache.bookkeeper.tests.integration.utils; +import edu.umd.cs.findbugs.annotations.SuppressFBWarnings; import java.util.concurrent.TimeUnit; import org.arquillian.cube.docker.impl.docker.DockerClientExecutor; import org.arquillian.cube.docker.impl.util.Ping; import org.arquillian.cube.docker.impl.util.PingCommand; import org.arquillian.cube.spi.Cube; import org.arquillian.cube.spi.await.AwaitStrategy; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; /** * An arquillian await strategy that waits until zookeeper is up running. */ +// `cube` and `dockerClientExecutor` are injected by Arquillian via reflection. +@SuppressFBWarnings({"UWF_UNWRITTEN_FIELD", "NP_UNWRITTEN_FIELD"}) public class ZooKeeperAwaitStrategy implements AwaitStrategy { - private static final Logger LOG = LoggerFactory.getLogger(ZooKeeperAwaitStrategy.class); private static final int DEFAULT_POLL_ITERATIONS = 10; private static final int DEFAULT_SLEEP_TIME = 1;