Introduce Testkit backend logging level support (#1406)

This update introduces support for setting logging levels in Testkit backend. The selected level and the logging is shared by both the backend and the drivers created by the backend.

The backend itself logs exchanges with the Testkit.

Example:
```
2023-04-06T13:20:14.769459 FINE neo4j.org.testkit.backend.channel.handler.TestkitRequestResponseMapperHandler - Inbound Testkit message '{"name": "NewSession", "data": {"driverId": "0", "accessMode": null, "bookmarks": null, "database": null, "fetchSize": null, "impersonatedUser": null, "notificationsMinSeverity": "WARNING"}}'
2023-04-06T13:20:14.781204 FINE neo4j.org.testkit.backend.channel.handler.TestkitRequestResponseMapperHandler - Outbound Testkit message '{"name":"Session","data":{"id":"1"}}'
```

The level is selected by setting a `TESTKIT_BACKEND_LOGGING_LEVEL` environment variable to one of the values supported by the `java.util.logging.Level.parse(String)`. The absence of the value or an empty string turns the logging off.

This feature is meant for debugging purposes only.

Author: injectives

testkit-backend/src/main/java/neo4j/org/testkit/backend/Runner.java

@@ -25,10 +25,12 @@
 import io.netty.channel.nio.NioEventLoopGroup;
 import io.netty.channel.socket.SocketChannel;
 import io.netty.channel.socket.nio.NioServerSocketChannel;
+import java.util.logging.Level;
 import neo4j.org.testkit.backend.channel.handler.TestkitMessageInboundHandler;
 import neo4j.org.testkit.backend.channel.handler.TestkitMessageOutboundHandler;
 import neo4j.org.testkit.backend.channel.handler.TestkitRequestProcessorHandler;
 import neo4j.org.testkit.backend.channel.handler.TestkitRequestResponseMapperHandler;
+import org.neo4j.driver.Logging;
 
 public class Runner {
     public static void main(String[] args) throws InterruptedException {
@@ -45,6 +47,10 @@ public static void main(String[] args) throws InterruptedException {
         } else {
             backendMode = TestkitRequestProcessorHandler.BackendMode.SYNC;
         }
+        var levelString = System.getenv("TESTKIT_BACKEND_LOGGING_LEVEL");
+        var logging = levelString == null || levelString.isEmpty()
+                ? Logging.none()
+                : Logging.console(Level.parse(levelString));
 
         EventLoopGroup group = new NioEventLoopGroup();
         try {
@@ -58,8 +64,8 @@ public static void main(String[] args) throws InterruptedException {
                         protected void initChannel(SocketChannel channel) {
                             channel.pipeline().addLast(new TestkitMessageInboundHandler());
                             channel.pipeline().addLast(new TestkitMessageOutboundHandler());
-                            channel.pipeline().addLast(new TestkitRequestResponseMapperHandler());
-                            channel.pipeline().addLast(new TestkitRequestProcessorHandler(backendMode));
+                            channel.pipeline().addLast(new TestkitRequestResponseMapperHandler(logging));
+                            channel.pipeline().addLast(new TestkitRequestProcessorHandler(backendMode, logging));
                         }
                     });
             ChannelFuture server = bootstrap.bind().sync();

testkit-backend/src/main/java/neo4j/org/testkit/backend/TestkitState.java

@@ -44,6 +44,7 @@
 import neo4j.org.testkit.backend.messages.requests.TestkitCallbackResult;
 import neo4j.org.testkit.backend.messages.responses.TestkitResponse;
 import org.neo4j.driver.BookmarkManager;
+import org.neo4j.driver.Logging;
 import org.neo4j.driver.internal.cluster.RoutingTableRegistry;
 import reactor.core.publisher.Mono;
 
@@ -76,6 +77,7 @@ public class TestkitState {
     private final Map<String, ReactiveTransactionStreamsHolder> transactionIdToReactiveTransactionStreamsHolder =
             new HashMap<>();
     private final Map<String, BookmarkManager> bookmarkManagerIdToBookmarkManager = new HashMap<>();
+    private final Logging logging;
 
     @Getter
     private final Map<String, Exception> errors = new HashMap<>();
@@ -88,8 +90,9 @@ public class TestkitState {
     @Getter
     private final Map<String, CompletableFuture<TestkitCallbackResult>> callbackIdToFuture = new HashMap<>();
 
-    public TestkitState(Consumer<TestkitResponse> responseWriter) {
+    public TestkitState(Consumer<TestkitResponse> responseWriter, Logging logging) {
         this.responseWriter = responseWriter;
+        this.logging = logging;
     }
 
     public String newId() {
@@ -238,6 +241,10 @@ public void removeBookmarkManager(String id) {
         }
     }
 
+    public Logging getLogging() {
+        return logging;
+    }
+
     private <T> String add(T value, Map<String, T> idToT) {
         String id = newId();
         idToT.put(id, value);

testkit-backend/src/main/java/neo4j/org/testkit/backend/channel/handler/TestkitRequestProcessorHandler.java

@@ -35,19 +35,20 @@
 import neo4j.org.testkit.backend.messages.responses.BackendError;
 import neo4j.org.testkit.backend.messages.responses.DriverError;
 import neo4j.org.testkit.backend.messages.responses.TestkitResponse;
+import org.neo4j.driver.Logging;
 import org.neo4j.driver.exceptions.Neo4jException;
 import org.neo4j.driver.exceptions.NoSuchRecordException;
 import org.neo4j.driver.exceptions.UntrustedServerException;
 import org.neo4j.driver.internal.spi.ConnectionPool;
 
 public class TestkitRequestProcessorHandler extends ChannelInboundHandlerAdapter {
-    private final TestkitState testkitState = new TestkitState(this::writeAndFlush);
+    private final TestkitState testkitState;
     private final BiFunction<TestkitRequest, TestkitState, CompletionStage<TestkitResponse>> processorImpl;
     // Some requests require multiple threads
     private final Executor requestExecutorService = Executors.newFixedThreadPool(10);
     private Channel channel;
 
-    public TestkitRequestProcessorHandler(BackendMode backendMode) {
+    public TestkitRequestProcessorHandler(BackendMode backendMode, Logging logging) {
         switch (backendMode) {
             case ASYNC:
                 processorImpl = TestkitRequest::processAsync;
@@ -63,6 +64,7 @@ public TestkitRequestProcessorHandler(BackendMode backendMode) {
                 processorImpl = TestkitRequestProcessorHandler::wrapSyncRequest;
                 break;
         }
+        testkitState = new TestkitState(this::writeAndFlush, logging);
     }
 
     @Override

testkit-backend/src/main/java/neo4j/org/testkit/backend/channel/handler/TestkitRequestResponseMapperHandler.java

@@ -26,13 +26,21 @@
 import neo4j.org.testkit.backend.messages.TestkitModule;
 import neo4j.org.testkit.backend.messages.requests.TestkitRequest;
 import neo4j.org.testkit.backend.messages.responses.TestkitResponse;
+import org.neo4j.driver.Logger;
+import org.neo4j.driver.Logging;
 
 public class TestkitRequestResponseMapperHandler extends ChannelDuplexHandler {
+    private final Logger log;
     private final ObjectMapper objectMapper = newObjectMapper();
 
+    public TestkitRequestResponseMapperHandler(Logging logging) {
+        log = logging.getLog(getClass());
+    }
+
     @Override
     public void channelRead(ChannelHandlerContext ctx, Object msg) throws Exception {
         String testkitMessage = (String) msg;
+        log.debug("Inbound Testkit message '%s'", testkitMessage.trim());
         TestkitRequest testkitRequest;
         testkitRequest = objectMapper.readValue(testkitMessage, TestkitRequest.class);
         ctx.fireChannelRead(testkitRequest);
@@ -42,6 +50,7 @@ public void channelRead(ChannelHandlerContext ctx, Object msg) throws Exception
     public void write(ChannelHandlerContext ctx, Object msg, ChannelPromise promise) throws Exception {
         TestkitResponse testkitResponse = (TestkitResponse) msg;
         String responseStr = objectMapper.writeValueAsString(testkitResponse);
+        log.debug("Outbound Testkit message '%s'", responseStr.trim());
         ctx.writeAndFlush(responseStr, promise);
     }
 

testkit-backend/src/main/java/neo4j/org/testkit/backend/messages/requests/NewDriver.java

@@ -118,6 +118,7 @@ public TestkitResponse process(TestkitState testkitState) {
         configBuilder.withNotificationConfig(
                 toNotificationConfig(data.notificationsMinSeverity, data.notificationsDisabledCategories));
         configBuilder.withDriverMetrics();
+        configBuilder.withLogging(testkitState.getLogging());
         org.neo4j.driver.Driver driver;
         Config config = configBuilder.build();
         try {