From e7a277d8f26381c255675df80cd345f1d9fac9ad Mon Sep 17 00:00:00 2001 From: Dmitriy Tverdiakov <11927660+injectives@users.noreply.github.com> Date: Thu, 6 Apr 2023 15:30:24 +0100 Subject: [PATCH] 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. --- .../main/java/neo4j/org/testkit/backend/Runner.java | 10 ++++++++-- .../java/neo4j/org/testkit/backend/TestkitState.java | 9 ++++++++- .../handler/TestkitRequestProcessorHandler.java | 6 ++++-- .../handler/TestkitRequestResponseMapperHandler.java | 9 +++++++++ .../testkit/backend/messages/requests/NewDriver.java | 1 + 5 files changed, 30 insertions(+), 5 deletions(-) diff --git a/testkit-backend/src/main/java/neo4j/org/testkit/backend/Runner.java b/testkit-backend/src/main/java/neo4j/org/testkit/backend/Runner.java index e3d76fa4b9..d518b4e8f1 100644 --- a/testkit-backend/src/main/java/neo4j/org/testkit/backend/Runner.java +++ b/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 { @@ -41,6 +43,10 @@ public static void main(String[] args) throws InterruptedException { } else { backendMode = TestkitRequestProcessorHandler.BackendMode.SYNC; } + String levelString = System.getenv("TESTKIT_BACKEND_LOGGING_LEVEL"); + Logging logging = levelString == null || levelString.isEmpty() + ? Logging.none() + : Logging.console(Level.parse(levelString)); EventLoopGroup group = new NioEventLoopGroup(); try { @@ -54,8 +60,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(); diff --git a/testkit-backend/src/main/java/neo4j/org/testkit/backend/TestkitState.java b/testkit-backend/src/main/java/neo4j/org/testkit/backend/TestkitState.java index 3ce1a58c13..80df9b0a40 100644 --- a/testkit-backend/src/main/java/neo4j/org/testkit/backend/TestkitState.java +++ b/testkit-backend/src/main/java/neo4j/org/testkit/backend/TestkitState.java @@ -37,6 +37,7 @@ import neo4j.org.testkit.backend.holder.TransactionHolder; import neo4j.org.testkit.backend.messages.requests.TestkitCallbackResult; import neo4j.org.testkit.backend.messages.responses.TestkitResponse; +import org.neo4j.driver.Logging; import org.neo4j.driver.internal.cluster.RoutingTableRegistry; import reactor.core.publisher.Mono; @@ -60,6 +61,7 @@ public class TestkitState { private final Map transactionIdToTransactionHolder = new HashMap<>(); private final Map transactionIdToAsyncTransactionHolder = new HashMap<>(); private final Map transactionIdToRxTransactionHolder = new HashMap<>(); + private final Logging logging; @Getter private final Map errors = new HashMap<>(); @@ -72,8 +74,9 @@ public class TestkitState { @Getter private final Map> callbackIdToFuture = new HashMap<>(); - public TestkitState(Consumer responseWriter) { + public TestkitState(Consumer responseWriter, Logging logging) { this.responseWriter = responseWriter; + this.logging = logging; } public String newId() { @@ -160,6 +163,10 @@ public Mono getRxResultHolder(String id) { return getRx(id, resultIdToRxResultHolder, RESULT_NOT_FOUND_MESSAGE); } + public Logging getLogging() { + return logging; + } + private String add(T value, Map idToT) { String id = newId(); idToT.put(id, value); diff --git a/testkit-backend/src/main/java/neo4j/org/testkit/backend/channel/handler/TestkitRequestProcessorHandler.java b/testkit-backend/src/main/java/neo4j/org/testkit/backend/channel/handler/TestkitRequestProcessorHandler.java index fdfc76fcc1..5dee37e739 100644 --- a/testkit-backend/src/main/java/neo4j/org/testkit/backend/channel/handler/TestkitRequestProcessorHandler.java +++ b/testkit-backend/src/main/java/neo4j/org/testkit/backend/channel/handler/TestkitRequestProcessorHandler.java @@ -33,18 +33,19 @@ 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.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> 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; @@ -56,6 +57,7 @@ public TestkitRequestProcessorHandler(BackendMode backendMode) { processorImpl = TestkitRequestProcessorHandler::wrapSyncRequest; break; } + testkitState = new TestkitState(this::writeAndFlush, logging); } @Override diff --git a/testkit-backend/src/main/java/neo4j/org/testkit/backend/channel/handler/TestkitRequestResponseMapperHandler.java b/testkit-backend/src/main/java/neo4j/org/testkit/backend/channel/handler/TestkitRequestResponseMapperHandler.java index 321feba4ce..f767cf0030 100644 --- a/testkit-backend/src/main/java/neo4j/org/testkit/backend/channel/handler/TestkitRequestResponseMapperHandler.java +++ b/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); } diff --git a/testkit-backend/src/main/java/neo4j/org/testkit/backend/messages/requests/NewDriver.java b/testkit-backend/src/main/java/neo4j/org/testkit/backend/messages/requests/NewDriver.java index eadbf7e36c..bb3fe25367 100644 --- a/testkit-backend/src/main/java/neo4j/org/testkit/backend/messages/requests/NewDriver.java +++ b/testkit-backend/src/main/java/neo4j/org/testkit/backend/messages/requests/NewDriver.java @@ -113,6 +113,7 @@ public TestkitResponse process(TestkitState testkitState) { Optional.ofNullable(data.connectionAcquisitionTimeoutMs) .ifPresent(timeout -> configBuilder.withConnectionAcquisitionTimeout(timeout, TimeUnit.MILLISECONDS)); configBuilder.withDriverMetrics(); + configBuilder.withLogging(testkitState.getLogging()); org.neo4j.driver.Driver driver; Config config = configBuilder.build(); try {