From d05eb2c329c83bc066800ec83548acc5aed538b6 Mon Sep 17 00:00:00 2001 From: Patrick Doyle Date: Wed, 24 Jan 2024 17:28:43 -0500 Subject: [PATCH] Logging MDC tweaks --- .../bosk/drivers/mongo/ChangeReceiver.java | 16 ++++++++++------ .../vena/bosk/drivers/mongo/MainDriver.java | 6 +++--- .../mongo/MappedDiagnosticContext.java | 19 ++++++++++++++----- .../io/vena/bosk/drivers/mongo/MdcKeys.java | 12 ++++++++++++ .../mongo/TransactionalCollection.java | 9 +++++---- lib-testing/src/main/resources/logback.xml | 2 +- 6 files changed, 45 insertions(+), 19 deletions(-) create mode 100644 bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/MdcKeys.java diff --git a/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/ChangeReceiver.java b/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/ChangeReceiver.java index 4f384126..2d6ed858 100644 --- a/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/ChangeReceiver.java +++ b/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/ChangeReceiver.java @@ -4,6 +4,8 @@ import com.mongodb.client.MongoChangeStreamCursor; import com.mongodb.client.MongoCollection; import com.mongodb.client.model.changestream.ChangeStreamDocument; +import io.vena.bosk.Bosk; +import io.vena.bosk.Identifier; import io.vena.bosk.drivers.mongo.MappedDiagnosticContext.MDCScope; import java.io.Closeable; import java.io.IOException; @@ -18,6 +20,7 @@ import org.slf4j.MDC; import static io.vena.bosk.drivers.mongo.MappedDiagnosticContext.setupMDC; +import static io.vena.bosk.drivers.mongo.MdcKeys.EVENT; import static java.lang.Thread.currentThread; import static java.util.concurrent.TimeUnit.MILLISECONDS; @@ -39,6 +42,7 @@ */ class ChangeReceiver implements Closeable { private final String boskName; + private final Identifier boskID; private final ChangeListener listener; private final MongoDriverSettings settings; private final MongoCollection collection; @@ -46,8 +50,9 @@ class ChangeReceiver implements Closeable { private final Exception creationPoint; private volatile boolean isClosed = false; - ChangeReceiver(String boskName, ChangeListener listener, MongoDriverSettings settings, MongoCollection collection) { + ChangeReceiver(String boskName, Identifier boskID, ChangeListener listener, MongoDriverSettings settings, MongoCollection collection) { this.boskName = boskName; + this.boskID = boskID; this.listener = listener; this.settings = settings; this.collection = collection; @@ -76,7 +81,7 @@ public void close() { private void connectionLoop() { String oldThreadName = currentThread().getName(); currentThread().setName(getClass().getSimpleName() + " [" + boskName + "]"); - try (MDCScope __ = setupMDC(boskName)) { + try (MDCScope __ = setupMDC(boskName, boskID)) { LOGGER.debug("Starting connectionLoop task"); try { while (!isClosed) { @@ -121,7 +126,7 @@ private void connectionLoop() { return; } } - } catch (UnprocessableEventException|UnexpectedEventProcessingException e) { + } catch (UnprocessableEventException | UnexpectedEventProcessingException e) { addContextToException(e); LOGGER.warn("Unable to process MongoDB change event; reconnecting ({})", e.getMessage(), e); listener.onDisconnect(e); @@ -249,7 +254,7 @@ private void processEvent(ChangeStreamDocument event) throws Unpro } } try { - MDC.put(MDC_KEY, "e" + EVENT_COUNTER.incrementAndGet()); + MDC.put(EVENT, "e" + EVENT_COUNTER.incrementAndGet()); switch (event.getOperationType()) { case INSERT: case UPDATE: @@ -265,11 +270,10 @@ private void processEvent(ChangeStreamDocument event) throws Unpro throw new UnprocessableEventException("Disruptive event received", event.getOperationType()); } } finally { - MDC.remove(MDC_KEY); + MDC.remove(EVENT); } } private static final AtomicLong EVENT_COUNTER = new AtomicLong(0); - public static final String MDC_KEY = "bosk.MongoDriver.event"; private static final Logger LOGGER = LoggerFactory.getLogger(ChangeReceiver.class); } diff --git a/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/MainDriver.java b/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/MainDriver.java index 10cfbcf7..05082e8a 100644 --- a/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/MainDriver.java +++ b/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/MainDriver.java @@ -81,7 +81,7 @@ class MainDriver implements MongoDriver { BsonPlugin bsonPlugin, BoskDriver downstream ) { - try (MDCScope __ = setupMDC(bosk.name())) { + try (MDCScope __ = setupMDC(bosk.name(), bosk.instanceID())) { this.bosk = bosk; this.driverSettings = driverSettings; this.bsonPlugin = bsonPlugin; @@ -102,7 +102,7 @@ class MainDriver implements MongoDriver { Type rootType = bosk.rootReference().targetType(); this.listener = new Listener(new FutureTask<>(() -> doInitialRoot(rootType))); this.formatter = new Formatter(bosk, bsonPlugin); - this.receiver = new ChangeReceiver(bosk.name(), listener, driverSettings, rawCollection); + this.receiver = new ChangeReceiver(bosk.name(), bosk.instanceID(), listener, driverSettings, rawCollection); } } @@ -510,7 +510,7 @@ private MDCScope beginDriverOperation(String description, Object... args) { if (isClosed) { throw new IllegalStateException("Driver is closed"); } - MDCScope ex = setupMDC(bosk.name()); + MDCScope ex = setupMDC(bosk.name(), bosk.instanceID()); LOGGER.debug(description, args); if (driverSettings.testing().eventDelayMS() < 0) { LOGGER.debug("| eventDelayMS {}ms ", driverSettings.testing().eventDelayMS()); diff --git a/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/MappedDiagnosticContext.java b/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/MappedDiagnosticContext.java index 60d9f4e0..e261d930 100644 --- a/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/MappedDiagnosticContext.java +++ b/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/MappedDiagnosticContext.java @@ -1,11 +1,17 @@ package io.vena.bosk.drivers.mongo; +import io.vena.bosk.Identifier; import org.slf4j.MDC; +import static io.vena.bosk.drivers.mongo.MdcKeys.BOSK_INSTANCE_ID; +import static io.vena.bosk.drivers.mongo.MdcKeys.BOSK_NAME; + final class MappedDiagnosticContext { - static MDCScope setupMDC(String boskName) { + + static MDCScope setupMDC(String boskName, Identifier boskID) { MDCScope result = new MDCScope(); - MDC.put(MDC_KEY, " [" + boskName + "]"); + MDC.put(BOSK_NAME, boskName); + MDC.put(BOSK_INSTANCE_ID, boskID.toString()); return result; } @@ -22,9 +28,12 @@ static MDCScope setupMDC(String boskName) { * You really want to use this in a try block that has no catch or finally clause. */ static final class MDCScope implements AutoCloseable { - final String oldValue = MDC.get(MDC_KEY); - @Override public void close() { MDC.put(MDC_KEY, oldValue); } + final String oldName = MDC.get(BOSK_NAME); + final String oldID = MDC.get(BOSK_INSTANCE_ID); + @Override public void close() { + MDC.put(BOSK_NAME, oldName); + MDC.put(BOSK_INSTANCE_ID, oldID); + } } - private static final String MDC_KEY = "bosk.MongoDriver"; } diff --git a/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/MdcKeys.java b/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/MdcKeys.java new file mode 100644 index 00000000..3100e72b --- /dev/null +++ b/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/MdcKeys.java @@ -0,0 +1,12 @@ +package io.vena.bosk.drivers.mongo; + +/** + * Evolution note: we're going to want to get organized in how we generate MDC. + * For now, it's all in bosk-mongo, so we can put these keys here. + */ +final class MdcKeys { + static final String BOSK_NAME = "bosk.name"; + static final String BOSK_INSTANCE_ID = "bosk.instanceID"; + static final String EVENT = "bosk.MongoDriver.event"; + static final String TRANSACTION = "bosk.MongoDriver.transaction"; +} diff --git a/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/TransactionalCollection.java b/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/TransactionalCollection.java index f8816e5c..61f4b423 100644 --- a/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/TransactionalCollection.java +++ b/bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/TransactionalCollection.java @@ -47,6 +47,8 @@ import org.slf4j.LoggerFactory; import org.slf4j.MDC; +import static io.vena.bosk.drivers.mongo.MdcKeys.TRANSACTION; + /** * A wrapper for {@link MongoCollection} that manages a thread-local * {@link ClientSession} so that operations can implicitly participate @@ -83,7 +85,7 @@ public class Session implements AutoCloseable { public Session(boolean isReadOnly) throws FailedSessionException { this.isReadOnly = isReadOnly; name = (isReadOnly? "r":"s") + identityCounter.getAndIncrement(); - oldMDC = MDC.get(MDC_KEY); + oldMDC = MDC.get(TRANSACTION); if (currentSession.get() != null) { // Note: we don't throw FailedSessionException because this // is not a transient exception that can be remedied by waiting @@ -106,7 +108,7 @@ public Session(boolean isReadOnly) throws FailedSessionException { throw new FailedSessionException(e); } currentSession.set(this); - MDC.put(MDC_KEY, name); + MDC.put(TRANSACTION, name); LOGGER.debug("Begin session"); } @@ -130,10 +132,9 @@ public void close() { LOGGER.debug("Close session"); clientSession.close(); currentSession.remove(); - MDC.put(MDC_KEY, oldMDC); + MDC.put(TRANSACTION, oldMDC); } - private static final String MDC_KEY = "bosk.MongoDriver.transaction"; } /** diff --git a/lib-testing/src/main/resources/logback.xml b/lib-testing/src/main/resources/logback.xml index 05b4f562..294adb7c 100644 --- a/lib-testing/src/main/resources/logback.xml +++ b/lib-testing/src/main/resources/logback.xml @@ -1,7 +1,7 @@ - %d %-5level [%thread]%X{MongoDriver}%X{MongoDriver.transaction}%X{MongoDriver.event} %logger{25}: %msg%n + %d %-5level [%thread] [%X{bosk.name}]%X{bosk.MongoDriver.transaction}%X{bosk.MongoDriver.event} %logger{25}: %msg%n true