From ddfcafd1dd1e7888b9fd12d36b3399f61915ddd3 Mon Sep 17 00:00:00 2001 From: Clement Escoffier Date: Tue, 19 Sep 2023 14:19:34 +0200 Subject: [PATCH] Rewrite the Vert.x MDC tests to be more robust --- .../quarkus/vertx/mdc/InMemoryLogHandler.java | 6 +- .../vertx/mdc/InMemoryLogHandlerProducer.java | 8 + .../quarkus/vertx/mdc/VerticleDeployer.java | 15 +- .../vertx/mdc/VertxMDCDevModeTest.java | 11 ++ .../io/quarkus/vertx/mdc/VertxMDCTest.java | 146 +++++++++--------- 5 files changed, 104 insertions(+), 82 deletions(-) diff --git a/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/InMemoryLogHandler.java b/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/InMemoryLogHandler.java index 5ee148fe88c72..ecc3d790b0529 100644 --- a/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/InMemoryLogHandler.java +++ b/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/InMemoryLogHandler.java @@ -13,12 +13,16 @@ public class InMemoryLogHandler extends Handler { private static final PatternFormatter FORMATTER = new PatternFormatter("%X{requestId} ### %s"); - private final List recordList = new CopyOnWriteArrayList<>(); + private static final List recordList = new CopyOnWriteArrayList<>(); public List logRecords() { return Collections.unmodifiableList(recordList); } + public static void reset() { + recordList.clear(); + } + @Override public void publish(LogRecord record) { String loggerName = record.getLoggerName(); diff --git a/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/InMemoryLogHandlerProducer.java b/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/InMemoryLogHandlerProducer.java index 844aea4a5200c..9155c27241feb 100644 --- a/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/InMemoryLogHandlerProducer.java +++ b/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/InMemoryLogHandlerProducer.java @@ -12,17 +12,25 @@ @ApplicationScoped public class InMemoryLogHandlerProducer { + public volatile boolean initialized = false; + @Produces @Singleton public InMemoryLogHandler inMemoryLogHandler() { return new InMemoryLogHandler(); } + public boolean isInitialized() { + return initialized; + } + void onStart(@Observes StartupEvent ev, InMemoryLogHandler inMemoryLogHandler) { InitialConfigurator.DELAYED_HANDLER.addHandler(inMemoryLogHandler); + initialized = true; } void onStop(@Observes ShutdownEvent ev, InMemoryLogHandler inMemoryLogHandler) { + initialized = false; InitialConfigurator.DELAYED_HANDLER.removeHandler(inMemoryLogHandler); } } diff --git a/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/VerticleDeployer.java b/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/VerticleDeployer.java index d2010e1c00d4c..5913631c420d8 100644 --- a/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/VerticleDeployer.java +++ b/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/VerticleDeployer.java @@ -12,10 +12,7 @@ import io.vertx.core.AbstractVerticle; import io.vertx.core.Promise; import io.vertx.core.http.HttpServer; -import io.vertx.core.json.JsonObject; -import io.vertx.ext.web.client.HttpRequest; import io.vertx.ext.web.client.WebClient; -import io.vertx.ext.web.codec.BodyCodec; import io.vertx.mutiny.core.Vertx; @ApplicationScoped @@ -42,22 +39,24 @@ void onStop(@Observes ShutdownEvent ev) { private static class TestVerticle extends AbstractVerticle { private static final Logger LOGGER = Logger.getLogger(TestVerticle.class); - private HttpRequest request; - @Override public void start(Promise startPromise) { WebClient webClient = WebClient.create(vertx); - request = webClient.getAbs("http://worldclockapi.com/api/json/utc/now").as(BodyCodec.jsonObject()); + var request = webClient.getAbs("http://localhost:" + VERTICLE_PORT + "/now"); Promise httpServerPromise = Promise.promise(); httpServerPromise.future(). mapEmpty().onComplete(startPromise); vertx.createHttpServer() .requestHandler(req -> { - String requestId = req.getHeader(REQUEST_ID_HEADER); + if (req.path().equals("/now")) { + req.response().end(Long.toString(System.currentTimeMillis())); + return; + } + + String requestId = req.getHeader(REQUEST_ID_HEADER); MDC.put(MDC_KEY, requestId); LOGGER.info("Received HTTP request ### " + MDC.get(MDC_KEY)); - vertx.setTimer(50, l -> { LOGGER.info("Timer fired ### " + MDC.get(MDC_KEY)); vertx.executeBlocking(() -> { diff --git a/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/VertxMDCDevModeTest.java b/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/VertxMDCDevModeTest.java index a8f9120532df1..b66c3ce71bdbc 100644 --- a/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/VertxMDCDevModeTest.java +++ b/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/VertxMDCDevModeTest.java @@ -3,12 +3,14 @@ import static io.quarkus.vertx.mdc.VerticleDeployer.REQUEST_ID_HEADER; import static io.quarkus.vertx.mdc.VerticleDeployer.VERTICLE_PORT; import static io.restassured.RestAssured.given; +import static org.awaitility.Awaitility.await; import static org.hamcrest.Matchers.is; import static org.junit.jupiter.api.Assertions.assertTrue; import java.nio.file.Files; import java.nio.file.Path; import java.nio.file.Paths; +import java.util.Arrays; import java.util.UUID; import java.util.concurrent.TimeUnit; @@ -19,6 +21,7 @@ import org.junit.jupiter.api.Test; import org.junit.jupiter.api.extension.RegisterExtension; +import io.quarkus.bootstrap.logging.InitialConfigurator; import io.quarkus.test.QuarkusDevModeTest; public class VertxMDCDevModeTest { @@ -34,6 +37,14 @@ public class VertxMDCDevModeTest { @Test void mdcDevMode() { + InMemoryLogHandler.reset(); + await().until(InitialConfigurator.DELAYED_HANDLER::isActivated); + await().until(() -> { + return Arrays.stream(InitialConfigurator.DELAYED_HANDLER.getHandlers()) + .anyMatch(h -> h.getClass().getName().contains("InMemoryLogHandler")); + }); + ; + Path logDirectory = Paths.get(".", "target"); String value = UUID.randomUUID().toString(); given().headers(REQUEST_ID_HEADER, value) diff --git a/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/VertxMDCTest.java b/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/VertxMDCTest.java index 9d42a80fbf728..ff803884ebac1 100644 --- a/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/VertxMDCTest.java +++ b/extensions/vertx/deployment/src/test/java/io/quarkus/vertx/mdc/VertxMDCTest.java @@ -5,17 +5,18 @@ import static java.util.stream.Collectors.groupingBy; import static java.util.stream.Collectors.mapping; import static java.util.stream.Collectors.toList; +import static org.awaitility.Awaitility.await; import static org.hamcrest.MatcherAssert.assertThat; import static org.hamcrest.Matchers.hasItem; import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertTrue; +import java.util.Arrays; import java.util.List; import java.util.Map; import java.util.UUID; import java.util.concurrent.CountDownLatch; -import java.util.concurrent.atomic.AtomicReference; -import java.util.function.Consumer; +import java.util.concurrent.TimeUnit; import java.util.stream.IntStream; import java.util.stream.Stream; @@ -25,14 +26,13 @@ import org.jboss.logging.MDC; import org.jboss.shrinkwrap.api.ShrinkWrap; import org.jboss.shrinkwrap.api.spec.JavaArchive; -import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.RepeatedTest; import org.junit.jupiter.api.extension.RegisterExtension; +import io.quarkus.bootstrap.logging.InitialConfigurator; import io.quarkus.test.QuarkusUnitTest; -import io.vertx.core.AsyncResult; -import io.vertx.core.CompositeFuture; import io.vertx.core.Future; -import io.vertx.core.Handler; import io.vertx.core.Vertx; import io.vertx.core.buffer.Buffer; import io.vertx.ext.web.client.HttpRequest; @@ -61,102 +61,102 @@ public class VertxMDCTest { @Inject InMemoryLogHandler inMemoryLogHandler; - + @Inject + InMemoryLogHandlerProducer producer; @Inject VerticleDeployer verticleDeployer; - static final CountDownLatch countDownLatch = new CountDownLatch(1); - static final AtomicReference errorDuringExecution = new AtomicReference<>(); - - @Test + @RepeatedTest(10) void mdc() throws Throwable { - List requestIds = IntStream.range(0, 10) + + InMemoryLogHandler.reset(); + await().until(() -> producer.isInitialized()); + await().until(InitialConfigurator.DELAYED_HANDLER::isActivated); + await().until(() -> { + return Arrays.stream(InitialConfigurator.DELAYED_HANDLER.getHandlers()).anyMatch(h -> h == inMemoryLogHandler); + }); + ; + + List requestIds = IntStream.range(0, 1) .mapToObj(i -> UUID.randomUUID().toString()) .collect(toList()); - sendRequests(requestIds, onSuccess(v -> { - try { - Map> allMessagesById = inMemoryLogHandler.logRecords() - .stream() - .map(line -> line.split(" ### ")) - .peek(split -> assertEquals(split[0], split[2])) - .collect(groupingBy(split -> split[0], - mapping(split -> split[1], toList()))); - - assertEquals(requestIds.size(), allMessagesById.size()); - assertTrue(requestIds.containsAll(allMessagesById.keySet())); - - List expected = Stream. builder() - .add("Received HTTP request") - .add("Timer fired") - .add("Blocking task executed") - .add("Received Web Client response") - .build() - .collect(toList()); - - for (List messages : allMessagesById.values()) { - assertEquals(expected, messages); - } - } catch (Throwable t) { - errorDuringExecution.set(t); - } finally { - countDownLatch.countDown(); - } - })); + CountDownLatch done = new CountDownLatch(1); + sendRequests(requestIds, done); + + Assertions.assertTrue(done.await(20, TimeUnit.SECONDS)); + + await().untilAsserted(() -> { + Map> allMessagesById = inMemoryLogHandler.logRecords() + .stream() + .map(line -> line.split(" ### ")) + .peek(split -> assertEquals(split[0], split[2])) + .collect(groupingBy(split -> split[0], + mapping(split -> split[1], toList()))); - countDownLatch.await(); + assertEquals(requestIds.size(), allMessagesById.size()); + assertTrue(requestIds.containsAll(allMessagesById.keySet())); - Throwable throwable = errorDuringExecution.get(); - if (throwable != null) { - throw throwable; - } + List expected = Stream. builder() + .add("Received HTTP request") + .add("Timer fired") + .add("Blocking task executed") + .add("Received Web Client response") + .build() + .collect(toList()); + + for (List messages : allMessagesById.values()) { + assertEquals(expected, messages); + } + }); } - @Test + @RepeatedTest(10) public void mdcNonVertxThreadTest() { + InMemoryLogHandler.reset(); + await().until(() -> producer.isInitialized()); + await().until(InitialConfigurator.DELAYED_HANDLER::isActivated); + await().until(() -> { + return Arrays.stream(InitialConfigurator.DELAYED_HANDLER.getHandlers()).anyMatch(h -> h == inMemoryLogHandler); + }); + ; + String mdcValue = "Test MDC value"; MDC.put("requestId", mdcValue); - LOGGER.info("Test 1"); - assertThat(inMemoryLogHandler.logRecords(), - hasItem(mdcValue + " ### Test 1")); + await().untilAsserted(() -> { + LOGGER.info("Test 1"); + assertThat(inMemoryLogHandler.logRecords(), hasItem(mdcValue + " ### Test 1")); + }); MDC.remove("requestId"); - LOGGER.info("Test 2"); - assertThat(inMemoryLogHandler.logRecords(), - hasItem(" ### Test 2")); + await().untilAsserted(() -> { + LOGGER.info("Test 2"); + assertThat(inMemoryLogHandler.logRecords(), hasItem(" ### Test 2")); + }); - mdcValue = "New test MDC value"; - MDC.put("requestId", mdcValue); - LOGGER.info("Test 3"); + String mdcValue2 = "New test MDC value"; + MDC.put("requestId", mdcValue2); - assertThat(inMemoryLogHandler.logRecords(), - hasItem(mdcValue + " ### Test 3")); - } - - protected Handler> onSuccess(Consumer consumer) { - return result -> { - if (result.failed()) { - errorDuringExecution.set(result.cause()); - countDownLatch.countDown(); - } else { - consumer.accept(result.result()); - } - }; + await().untilAsserted(() -> { + LOGGER.info("Test 3"); + assertThat(inMemoryLogHandler.logRecords(), hasItem(mdcValue2 + " ### Test 3")); + }); } - @SuppressWarnings({ "rawtypes" }) - private void sendRequests(List ids, Handler> handler) { + private void sendRequests(List ids, CountDownLatch done) { WebClient webClient = WebClient.create(vertx, new WebClientOptions().setDefaultPort(VERTICLE_PORT)); HttpRequest request = webClient.get("/") .expect(ResponsePredicate.SC_OK); - List futures = ids.stream() + List> futures = ids.stream() .map(id -> request.putHeader(REQUEST_ID_HEADER, id).send()) .collect(toList()); - CompositeFuture.all(futures). mapEmpty().onComplete(handler); + Future.all(futures).mapEmpty().onComplete(x -> { + done.countDown(); + }); } }