Logging MDC tweaks (#93)

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,15 +42,17 @@
  */
 class ChangeReceiver implements Closeable {
 	private final String boskName;
+	private final Identifier boskID;
 	private final ChangeListener listener;
 	private final MongoDriverSettings settings;
 	private final MongoCollection<BsonDocument> collection;
 	private final ScheduledExecutorService ex = Executors.newScheduledThreadPool(1);
 	private final Exception creationPoint;
 	private volatile boolean isClosed = false;
 
-	ChangeReceiver(String boskName, ChangeListener listener, MongoDriverSettings settings, MongoCollection<BsonDocument> collection) {
+	ChangeReceiver(String boskName, Identifier boskID, ChangeListener listener, MongoDriverSettings settings, MongoCollection<BsonDocument> 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<BsonDocument> 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<BsonDocument> 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);
 }

bosk-mongo/src/main/java/io/vena/bosk/drivers/mongo/MainDriver.java

@@ -81,7 +81,7 @@ class MainDriver<R extends StateTreeNode> implements MongoDriver<R> {
 		BsonPlugin bsonPlugin,
 		BoskDriver<R> 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<R extends StateTreeNode> implements MongoDriver<R> {
 			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());

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";
 }

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";
+}

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";
 	}
 
 	/**

lib-testing/src/main/resources/logback.xml

@@ -1,7 +1,7 @@
 <configuration>
 	<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
 		<encoder>
-			<pattern>%d %-5level [%thread]%X{MongoDriver}%X{MongoDriver.transaction}%X{MongoDriver.event} %logger{25}: %msg%n</pattern>
+			<pattern>%d %-5level [%thread] [%X{bosk.name}]%X{bosk.MongoDriver.transaction}%X{bosk.MongoDriver.event} %logger{25}: %msg%n</pattern>
 		</encoder>
 		<immediateFlush>true</immediateFlush>
 	</appender>