Skip to content

Commit 22a37ec

Browse files
merlimatmerlimat
authored
BP-69: Convert stats and allocator modules to slog (phase 2) (#4755)
* BP-69 base: add slog dependency and LICENSE entries Minimal scaffolding commit for the BP-69 slog migration series: - Add `io.github.merlimat.slog:slog:0.9.7` to the root pom.xml dependencyManagement and to the global compile classpath alongside the existing SLF4J API (which stays as the rendering backend). - Add lombok.config at the repo root so `@CustomLog` generates a slog `Logger` instead of an SLF4J one. - Register the slog jar in LICENSE-all.bin.txt, LICENSE-server.bin.txt and LICENSE-bkctl.bin.txt so the CI check-binary-license script finds it accounted for in the bundled-jars list. No actual Java file is converted in this commit. Individual module migrations stack on top of this one. * BP-69: Convert stats and allocator modules from SLF4J to slog Part of BP-69. Converts the stats-api, codahale/otel/prometheus metrics providers, stats-utils, and bookkeeper-common-allocator modules. * Fix checkstyle ImportOrder violations * Bump slog dependency to 0.9.8 Pulls in the MDC propagation fix from merlimat/slog#6, which makes log4j2 ThreadContext entries visible on slog events emitted via the Log4j2Logger backend (so %X{key} layouts and appenders that read event.getContextData().getValue(key) see the caller's MDC).
1 parent ed71a06 commit 22a37ec

12 files changed

Lines changed: 80 additions & 74 deletions

File tree

‎bookkeeper-common-allocator/src/main/java/org/apache/bookkeeper/common/allocator/impl/ByteBufAllocatorImpl.java‎

Lines changed: 6 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -25,21 +25,19 @@
2525
import io.netty.util.ResourceLeakDetector;
2626
import io.netty.util.ResourceLeakDetector.Level;
2727
import java.util.function.Consumer;
28+
import lombok.CustomLog;
2829
import org.apache.bookkeeper.common.allocator.ByteBufAllocatorWithOomHandler;
2930
import org.apache.bookkeeper.common.allocator.LeakDetectionPolicy;
3031
import org.apache.bookkeeper.common.allocator.OutOfMemoryPolicy;
3132
import org.apache.bookkeeper.common.allocator.PoolingPolicy;
3233
import org.apache.bookkeeper.common.util.ShutdownUtil;
33-
import org.slf4j.Logger;
34-
import org.slf4j.LoggerFactory;
3534

3635
/**
3736
* Implementation of {@link ByteBufAllocator}.
3837
*/
38+
@CustomLog
3939
public class ByteBufAllocatorImpl extends AbstractByteBufAllocator implements ByteBufAllocatorWithOomHandler {
4040

41-
private static final Logger log = LoggerFactory.getLogger(ByteBufAllocatorImpl.class);
42-
4341
// Same as AbstractByteBufAllocator, but copied here since it's not visible
4442
private static final int DEFAULT_INITIAL_CAPACITY = 256;
4543
private static final int DEFAULT_MAX_CAPACITY = Integer.MAX_VALUE;
@@ -69,7 +67,7 @@ public class ByteBufAllocatorImpl extends AbstractByteBufAllocator implements By
6967
this.exitOnOutOfMemory = exitOnOutOfMemory;
7068
if (outOfMemoryListener == null) {
7169
this.outOfMemoryListener = (v) -> {
72-
log.error("Unable to allocate memory", v);
70+
log.error().exception(v).log("Unable to allocate memory");
7371
};
7472
} else {
7573
this.outOfMemoryListener = outOfMemoryListener;
@@ -105,9 +103,7 @@ public class ByteBufAllocatorImpl extends AbstractByteBufAllocator implements By
105103
// allocators
106104
switch (leakDetectionPolicy) {
107105
case Disabled:
108-
if (log.isDebugEnabled()) {
109-
log.debug("Disable Netty allocator leak detector");
110-
}
106+
log.debug("Disable Netty allocator leak detector");
111107
ResourceLeakDetector.setLevel(Level.DISABLED);
112108
break;
113109

@@ -201,10 +197,10 @@ private void consumeOOMError(OutOfMemoryError outOfMemoryError) {
201197
try {
202198
outOfMemoryListener.accept(outOfMemoryError);
203199
} catch (Throwable e) {
204-
log.warn("Consume outOfMemory error failed.", e);
200+
log.warn().exception(e).log("Consume outOfMemory error failed");
205201
}
206202
if (exitOnOutOfMemory) {
207-
log.info("Exiting JVM process for OOM error: {}", outOfMemoryError.getMessage(), outOfMemoryError);
203+
log.info().exception(outOfMemoryError).log("Exiting JVM process for OOM error");
208204
ShutdownUtil.triggerImmediateForcefulShutdown();
209205
}
210206
}

‎stats/bookkeeper-stats-api/src/main/java/org/apache/bookkeeper/stats/AlertStatsLogger.java‎

Lines changed: 3 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -16,14 +16,13 @@
1616
*/
1717
package org.apache.bookkeeper.stats;
1818

19-
import org.slf4j.Logger;
20-
import org.slf4j.LoggerFactory;
19+
import lombok.CustomLog;
2120

2221
/**
2322
* This class is used to raise alert when we detect an event that should never happen in production.
2423
*/
24+
@CustomLog
2525
public class AlertStatsLogger {
26-
private static final Logger logger = LoggerFactory.getLogger(AlertStatsLogger.class);
2726

2827
public final String alertStatName;
2928

@@ -73,7 +72,6 @@ public void raise(String msg, Object... args) {
7372
if (null != scopedCounter) {
7473
scopedCounter.inc();
7574
}
76-
logger.error(format(msg), args);
77-
logger.error("fake exception to generate stack trace", new Exception());
75+
log.error().exception(new Exception()).logf(format(msg), args);
7876
}
7977
}

‎stats/bookkeeper-stats-api/src/main/java/org/apache/bookkeeper/stats/Stats.java‎

Lines changed: 19 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -23,15 +23,14 @@
2323
import edu.umd.cs.findbugs.annotations.SuppressFBWarnings;
2424
import java.lang.reflect.Constructor;
2525
import java.lang.reflect.InvocationTargetException;
26+
import lombok.CustomLog;
2627
import org.apache.commons.configuration2.Configuration;
27-
import org.slf4j.Logger;
28-
import org.slf4j.LoggerFactory;
2928

3029
/**
3130
* An umbrella class for loading stats provider.
3231
*/
32+
@CustomLog
3333
public class Stats {
34-
static final Logger LOG = LoggerFactory.getLogger(Stats.class);
3534
public static final String STATS_PROVIDER_CLASS = "statsProviderClass";
3635

3736
static StatsProvider prov = new NullStatsProvider();
@@ -50,16 +49,27 @@ public static void loadStatsProvider(String className) {
5049
(Constructor<? extends StatsProvider>) cls.getDeclaredConstructor();
5150
prov = cons.newInstance();
5251
} catch (ClassNotFoundException cnfe) {
53-
LOG.error("Couldn't find configured class(" + className + ")", cnfe);
52+
log.error()
53+
.exception(cnfe)
54+
.attr("className", className)
55+
.log("Couldn't find configured class");
5456
} catch (NoSuchMethodException nsme) {
55-
LOG.error("Couldn't find default constructor for class (" + className + ")", nsme);
57+
log.error()
58+
.exception(nsme)
59+
.attr("className", className)
60+
.log("Couldn't find default constructor for class");
5661
} catch (InstantiationException ie) {
57-
LOG.error("Couldn't construct class (" + className + ")", ie);
62+
log.error()
63+
.exception(ie)
64+
.attr("className", className)
65+
.log("Couldn't construct class");
5866
} catch (IllegalAccessException iae) {
59-
LOG.error("Couldn't construct class (" + className + "),"
60-
+ " Is the constructor private?", iae);
67+
log.error()
68+
.exception(iae)
69+
.attr("className", className)
70+
.log("Couldn't construct class, is the constructor private?");
6171
} catch (InvocationTargetException ite) {
62-
LOG.error("Constructor threw an exception. It should not have.", ite);
72+
log.error().exception(ite).log("Constructor threw an exception. It should not have.");
6373
}
6474
}
6575
}

‎stats/bookkeeper-stats-api/src/main/java/org/apache/bookkeeper/stats/ThreadRegistry.java‎

Lines changed: 6 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -18,17 +18,16 @@
1818

1919
import java.util.concurrent.ConcurrentHashMap;
2020
import java.util.concurrent.ConcurrentMap;
21-
import org.slf4j.Logger;
22-
import org.slf4j.LoggerFactory;
21+
import lombok.CustomLog;
2322

2423
/**
2524
* For mapping thread ids to thread pools and threads within those pools
2625
* or just for lone named threads. Thread scoped metrics add labels to
2726
* metrics by retrieving the ThreadPoolThread object from this registry.
2827
* For flexibility, this registry is not based on TLS.
2928
*/
29+
@CustomLog
3030
public class ThreadRegistry {
31-
private static Logger logger = LoggerFactory.getLogger(ThreadRegistry.class);
3231
private static ConcurrentMap<Long, ThreadPoolThread> threadPoolMap = new ConcurrentHashMap<>();
3332
private static ConcurrentMap<String, Integer> threadPoolThreadMap = new ConcurrentHashMap<>();
3433

@@ -59,7 +58,10 @@ public static void register(String threadPool, boolean force) {
5958
public static void forceClearRegistrationForTests(long threadId) {
6059
threadPoolMap.compute(threadId, (id, value) -> {
6160
if (value != null) {
62-
logger.info("Forcibly clearing registry entry {} for thread id {}", value, id);
61+
log.info()
62+
.attr("entry", value)
63+
.attr("threadId", id)
64+
.log("Forcibly clearing registry entry");
6365
}
6466
return null;
6567
});

‎stats/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/CodahaleMetricsProvider.java‎

Lines changed: 6 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -33,21 +33,20 @@
3333
import java.util.ArrayList;
3434
import java.util.List;
3535
import java.util.concurrent.TimeUnit;
36+
import lombok.CustomLog;
3637
import org.apache.bookkeeper.stats.StatsLogger;
3738
import org.apache.bookkeeper.stats.StatsProvider;
3839
import org.apache.bookkeeper.stats.ThreadRegistry;
3940
import org.apache.commons.configuration2.Configuration;
40-
import org.slf4j.Logger;
4141
import org.slf4j.LoggerFactory;
4242

4343
/**
4444
* A {@link StatsProvider} implemented based on <i>Codahale</i> metrics library.
4545
*/
4646
@SuppressWarnings("deprecation")
47+
@CustomLog
4748
public class CodahaleMetricsProvider implements StatsProvider {
4849

49-
static final Logger LOG = LoggerFactory.getLogger(CodahaleMetricsProvider.class);
50-
5150
MetricRegistry metrics = null;
5251
List<ScheduledReporter> reporters = new ArrayList<ScheduledReporter>();
5352
JmxReporter jmx = null;
@@ -76,7 +75,7 @@ public void start(Configuration conf) {
7675
String jmxDomain = conf.getString("codahaleStatsJmxEndpoint");
7776

7877
if (!Strings.isNullOrEmpty(graphiteHost)) {
79-
LOG.info("Configuring stats with graphite");
78+
log.info("Configuring stats with graphite");
8079
HostAndPort addr = HostAndPort.fromString(graphiteHost);
8180
final Graphite graphite = new Graphite(
8281
new InetSocketAddress(addr.getHost(), addr.getPort()));
@@ -97,22 +96,22 @@ public void start(Configuration conf) {
9796
} else {
9897
outdir = new File(csvDir);
9998
}
100-
LOG.info("Configuring stats with csv output to directory [{}]", outdir.getAbsolutePath());
99+
log.info().attr("directory", outdir.getAbsolutePath()).log("Configuring stats with csv output");
101100
reporters.add(CsvReporter.forRegistry(getMetrics())
102101
.convertRatesTo(TimeUnit.SECONDS)
103102
.convertDurationsTo(TimeUnit.MILLISECONDS)
104103
.build(outdir));
105104
}
106105
if (!Strings.isNullOrEmpty(slf4jCat)) {
107-
LOG.info("Configuring stats with slf4j");
106+
log.info("Configuring stats with slf4j");
108107
reporters.add(Slf4jReporter.forRegistry(getMetrics())
109108
.outputTo(LoggerFactory.getLogger(slf4jCat))
110109
.convertRatesTo(TimeUnit.SECONDS)
111110
.convertDurationsTo(TimeUnit.MILLISECONDS)
112111
.build());
113112
}
114113
if (!Strings.isNullOrEmpty(jmxDomain)) {
115-
LOG.info("Configuring stats with jmx");
114+
log.info("Configuring stats with jmx");
116115
jmx = JmxReporter.forRegistry(getMetrics())
117116
.inDomain(jmxDomain)
118117
.convertRatesTo(TimeUnit.SECONDS)

‎stats/bookkeeper-stats-providers/otel-metrics-provider/src/main/java/org/apache/bookkeeper/stats/otel/OtelMetricsProvider.java‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -43,13 +43,13 @@
4343
import java.util.concurrent.ConcurrentMap;
4444
import java.util.concurrent.atomic.AtomicLong;
4545
import java.util.function.Supplier;
46-
import lombok.extern.slf4j.Slf4j;
46+
import lombok.CustomLog;
4747
import org.apache.bookkeeper.stats.StatsLogger;
4848
import org.apache.bookkeeper.stats.StatsProvider;
4949
import org.apache.commons.configuration2.Configuration;
5050
// CHECKSTYLE.ON: IllegalImport
5151

52-
@Slf4j
52+
@CustomLog
5353
public class OtelMetricsProvider implements StatsProvider {
5454

5555
private static final String METER_NAME = "org.apache.bookkeeper";
@@ -136,7 +136,7 @@ public StatsLogger getStatsLogger(String scope) {
136136
field.setAccessible(true);
137137
tmpDirectMemoryUsage = (AtomicLong) field.get(null);
138138
} catch (Throwable t) {
139-
log.warn("Failed to access netty DIRECT_MEMORY_COUNTER field {}", t.getMessage());
139+
log.warn().exceptionMessage(t).log("Failed to access netty DIRECT_MEMORY_COUNTER field");
140140
}
141141
directMemoryUsage = tmpDirectMemoryUsage;
142142
getDirectMemoryUsage = () -> directMemoryUsage != null ? directMemoryUsage.get() : Double.NaN;

‎stats/bookkeeper-stats-providers/prometheus-metrics-provider/src/main/java/org/apache/bookkeeper/stats/prometheus/PrometheusMetricsProvider.java‎

Lines changed: 6 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -44,6 +44,7 @@
4444
import java.util.concurrent.TimeUnit;
4545
import java.util.concurrent.atomic.AtomicLong;
4646
import java.util.function.Supplier;
47+
import lombok.CustomLog;
4748
import org.apache.bookkeeper.stats.StatsLogger;
4849
import org.apache.bookkeeper.stats.StatsProvider;
4950
import org.apache.bookkeeper.stats.ThreadRegistry;
@@ -52,13 +53,12 @@
5253
import org.eclipse.jetty.ee8.servlet.ServletContextHandler;
5354
import org.eclipse.jetty.ee8.servlet.ServletHolder;
5455
import org.eclipse.jetty.server.Server;
55-
import org.slf4j.Logger;
56-
import org.slf4j.LoggerFactory;
5756
// CHECKSTYLE.ON: IllegalImport
5857

5958
/**
6059
* A <i>Prometheus</i> based {@link StatsProvider} implementation.
6160
*/
61+
@CustomLog
6262
public class PrometheusMetricsProvider implements StatsProvider {
6363

6464
private ScheduledExecutorService executor;
@@ -117,7 +117,7 @@ public void start(Configuration conf) {
117117

118118
try {
119119
server.start();
120-
log.info("Started Prometheus stats endpoint at {}", httpEndpoint);
120+
log.info().attr("endpoint", httpEndpoint).log("Started Prometheus stats endpoint");
121121
} catch (Exception e) {
122122
throw new RuntimeException(e);
123123
}
@@ -163,7 +163,7 @@ public void stop() {
163163
try {
164164
server.stop();
165165
} catch (Exception e) {
166-
log.warn("Failed to shutdown Jetty server", e);
166+
log.warn().exception(e).log("Failed to shutdown Jetty server");
167167
} finally {
168168
ThreadRegistry.clear();
169169
}
@@ -211,14 +211,10 @@ private void registerMetrics(Collector collector) {
211211
collector.register(registry);
212212
} catch (Exception e) {
213213
// Ignore if these were already registered
214-
if (log.isDebugEnabled()) {
215-
log.debug("Failed to register Prometheus collector exports", e);
216-
}
214+
log.debug().exception(e).log("Failed to register Prometheus collector exports");
217215
}
218216
}
219217

220-
private static final Logger log = LoggerFactory.getLogger(PrometheusMetricsProvider.class);
221-
222218
/*
223219
* Try to get Netty counter of used direct memory. This will be correct, unlike the JVM values.
224220
*/
@@ -235,7 +231,7 @@ private void registerMetrics(Collector collector) {
235231
field.setAccessible(true);
236232
tmpDirectMemoryUsage = (AtomicLong) field.get(null);
237233
} catch (Throwable t) {
238-
log.warn("Failed to access netty DIRECT_MEMORY_COUNTER field {}", t.getMessage());
234+
log.warn().exceptionMessage(t).log("Failed to access netty DIRECT_MEMORY_COUNTER field");
239235
}
240236
directMemoryUsage = tmpDirectMemoryUsage;
241237
getDirectMemoryUsage = () -> directMemoryUsage != null ? directMemoryUsage.get() : Double.NaN;

‎stats/bookkeeper-stats-providers/prometheus-metrics-provider/src/main/java/org/apache/bookkeeper/stats/prometheus/ThreadScopedDataSketchesStatsLogger.java‎

Lines changed: 14 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -19,20 +19,18 @@
1919
import java.util.HashMap;
2020
import java.util.Map;
2121
import java.util.concurrent.TimeUnit;
22+
import lombok.CustomLog;
2223
import org.apache.bookkeeper.stats.OpStatsData;
2324
import org.apache.bookkeeper.stats.OpStatsLogger;
2425
import org.apache.bookkeeper.stats.ThreadRegistry;
25-
import org.slf4j.Logger;
26-
import org.slf4j.LoggerFactory;
2726

2827
/**
2928
* OpStatsLogger implementation that lazily registers OpStatsLoggers per thread
3029
* with added labels for the threadpool/thresd name and thread no.
3130
*/
31+
@CustomLog
3232
public class ThreadScopedDataSketchesStatsLogger implements OpStatsLogger {
3333

34-
private static Logger logger = LoggerFactory.getLogger(ThreadScopedDataSketchesStatsLogger.class);
35-
3634
private ThreadLocal<DataSketchesOpStatsLogger> statsLoggers;
3735
private DataSketchesOpStatsLogger defaultStatsLogger;
3836
private Map<String, String> originalLabels;
@@ -99,16 +97,19 @@ private DataSketchesOpStatsLogger getStatsLogger() {
9997
if (!statsLogger.isThreadInitialized()) {
10098
ThreadRegistry.ThreadPoolThread tpt = ThreadRegistry.get();
10199
if (tpt == null) {
102-
logger.warn("Thread {} was not registered in the thread registry. Using default stats logger {}.",
103-
Thread.currentThread(), defaultStatsLogger);
100+
log.warn()
101+
.attr("thread", Thread.currentThread())
102+
.attr("statsLogger", defaultStatsLogger)
103+
.log("Thread was not registered in the thread registry. Using default stats logger");
104104
statsLoggers.set(defaultStatsLogger);
105105
DataSketchesOpStatsLogger previous = provider.opStats
106106
.put(new ScopeContext(scopeContext.getScope(), originalLabels), defaultStatsLogger);
107107
// If we overwrite a logger, metrics will not be collected correctly
108108
if (previous != null && previous != defaultStatsLogger) {
109-
logger.error("Invalid state for thead " + Thread.currentThread() + ". Overwrote a stats logger."
110-
+ "New is {}, previous was {}",
111-
defaultStatsLogger, previous);
109+
log.error()
110+
.attr("thread", Thread.currentThread())
111+
.attr("newLogger", defaultStatsLogger)
112+
.attr("previousLogger", previous).log("Invalid state. Overwrote a stats logger");
112113
throw new IllegalStateException("Invalid state. Overwrote a stats logger.");
113114
}
114115
return defaultStatsLogger;
@@ -122,9 +123,10 @@ private DataSketchesOpStatsLogger getStatsLogger() {
122123
.put(new ScopeContext(scopeContext.getScope(), threadScopedlabels), statsLogger);
123124
// If we overwrite a logger, metrics will not be collected correctly
124125
if (previous != null && previous != statsLogger) {
125-
logger.error("Invalid state for thead " + Thread.currentThread() + ". Overwrote a stats logger."
126-
+ "New is {}, previous was {}",
127-
defaultStatsLogger, previous);
126+
log.error()
127+
.attr("thread", Thread.currentThread())
128+
.attr("newLogger", defaultStatsLogger)
129+
.attr("previousLogger", previous).log("Invalid state. Overwrote a stats logger");
128130
throw new IllegalStateException("Invalid state. Overwrote a stats logger.");
129131
}
130132
}

0 commit comments

Comments
 (0)