helidon-io / helidon

Java libraries for writing microservices
https://helidon.io
Apache License 2.0
3.5k stars 566 forks source link

Contexts.wrap is not propagating MDC data when used in webserver (Helidon 4.0.9 SE) request execution flow. #8935

Closed vamseeds closed 2 months ago

vamseeds commented 3 months ago

Environment Details


Problem Description

Current Behaviour:

Helidon MDC Context is not propagated when we use a async code activity like creating CompletableFuture or ExecutorService to executing code

Expected Behaviour:

Helidon MDC Context should be propagated when we use a async code activity like creating CompletableFuture or ExecutorService to executing code

Consistency: Above problem is consistent Sample code: ExecutorService newEs = Contexts.wrap(Executors.newSingleThreadExecutor()); CompletableFuture.runAsync(() -> LOGGER.info("Running on newES thread {}", HelidonMdc.get("foo")),newEs);

Steps to reproduce

@Override
    public void routing(HttpRules rules) {
        rules
                .get("/", this::getDefaultMessageHandler)
                .get("/{name}", this::getMessageHandler)
                .put("/greeting", this::updateGreetingHandler);
    }

    private void getDefaultMessageHandler(ServerRequest request,
                                          ServerResponse response) {
        LOGGER.atInfo().log("getDefaultMessageHandler");
        logging();
        sendResponse(response, "World");
    }

private void logging() {
        LOGGER.info("In Logging method");
        Optional<String> s = HelidonMdc.get(LoggingConstants.MDC_OPERATION);
        HelidonMdc.set("foo", "bar");
        ExecutorService es = Contexts.wrap(Executors.newSingleThreadExecutor());
        Future<?> submit = es.submit(this::log);
        try {
            submit.get();
        } catch (Exception e) {
            e.printStackTrace();
        }
        es.shutdown();

        LOGGER.info("Done with Logging method");
        ExecutorService newEs = Contexts.wrap(Executors.newSingleThreadExecutor());

        CompletableFuture.runAsync(() -> LOGGER.info("Running on newES thread {}", HelidonMdc.get("foo")),newEs);
    }

    private void log() {
        Optional<String> s = HelidonMdc.get(LoggingConstants.MDC_OPERATION);
        LOGGER.info("Running on another thread {}", HelidonMdc.get("foo")
        );
    }

Current Output:

2024-07-02 11:58:06.958 | GET | cdef:Apache-HttpClient/4.5.14 (Java/17.0.10):REST:62e3dda2-7597-4747-839c-6bd8ef0aa5f0 | [0x4aa92b53 0x37ab079c] WebServer socket | INFO | com.explore.logging.log4j2.with.mdc.GreetService - getDefaultMessageHandler post webclient call Hello World! 2024-07-02 11:58:06.958 | GET | cdef:Apache-HttpClient/4.5.14 (Java/17.0.10):REST:62e3dda2-7597-4747-839c-6bd8ef0aa5f0 | [0x4aa92b53 0x37ab079c] WebServer socket | INFO | com.explore.logging.log4j2.with.mdc.GreetService - In Logging method 2024-07-02 11:58:06.959 | | ::: | pool-3-thread-1 | INFO | com.explore.logging.log4j2.with.mdc.GreetService - Running on another thread Optional.empty 2024-07-02 11:58:06.959 | GET | cdef:Apache-HttpClient/4.5.14 (Java/17.0.10):REST:62e3dda2-7597-4747-839c-6bd8ef0aa5f0 | [0x4aa92b53 0x37ab079c] WebServer socket | INFO | com.explore.logging.log4j2.with.mdc.GreetService - Done with Logging method 2024-07-02 11:58:06.959 | | ::: | pool-4-thread-1 | INFO | com.explore.logging.log4j2.with.mdc.GreetService - Running on another thread Optional.empty 2024-07-02 11:58:06.963 | GET | cdef:Apache-HttpClient/4.5.14 (Java/17.0.10):REST:62e3dda2-7597-4747-839c-6bd8ef0aa5f0 | [0x4aa92b53 0x37ab079c] WebServer socket | DEBUG | io.helidon.webserver.http1.Http1LoggingConnectionListener.send - [0x4aa92b53 0x37ab079c] send status: 200 OK

Expected Output:

2024-07-02 12:16:33.643 | GET | cdef:Apache-HttpClient/4.5.14 (Java/17.0.10):REST:11329be7-96a8-4136-9d97-231e382dbd83 | [0x4bf5ea79 0x2c97c89c] WebServer socket | INFO | com.explore.logging.log4j2.with.mdc.GreetService - getDefaultMessageHandler post webclient call Hello World! 2024-07-02 12:16:33.643 | GET | cdef:Apache-HttpClient/4.5.14 (Java/17.0.10):REST:11329be7-96a8-4136-9d97-231e382dbd83 | [0x4bf5ea79 0x2c97c89c] WebServer socket | INFO | com.explore.logging.log4j2.with.mdc.GreetService - In Logging method 2024-07-02 12:16:33.644 | GET | cdef:Apache-HttpClient/4.5.14 (Java/17.0.10):REST:11329be7-96a8-4136-9d97-231e382dbd83 | pool-3-thread-1 | INFO | com.explore.logging.log4j2.with.mdc.GreetService - Running on another thread Optional[bar] 2024-07-02 12:16:33.644 | GET | cdef:Apache-HttpClient/4.5.14 (Java/17.0.10):REST:11329be7-96a8-4136-9d97-231e382dbd83 | [0x4bf5ea79 0x2c97c89c] WebServer socket | INFO | com.explore.logging.log4j2.with.mdc.GreetService - Done with Logging method 2024-07-02 12:16:33.644 | GET | cdef:Apache-HttpClient/4.5.14 (Java/17.0.10):REST:11329be7-96a8-4136-9d97-231e382dbd83 | pool-4-thread-1 | INFO | com.explore.logging.log4j2.with.mdc.GreetService - Running on newES thread Optional[bar] 2024-07-02 12:16:33.647 | GET | cdef:Apache-HttpClient/4.5.14 (Java/17.0.10):REST:11329be7-96a8-4136-9d97-231e382dbd83 | [0x4bf5ea79 0x2c97c89c] WebServer socket | DEBUG | io.helidon.webserver.http1.Http1LoggingConnectionListener.send - [0x4bf5ea79 0x2c97c89c] send status: 200 OK

Verdent commented 3 months ago

The issue here is, that MDC propagation is not currently happening, when Helidon Context is not prosent. I took a look into the code and could not find a reason, why it should not. This should be changed.

Verdent commented 2 months ago

To make this work before fix will be out, please add the following dependency

<dependency>
    <groupId>io.helidon.webserver</groupId>
    <artifactId>helidon-webserver-context</artifactId>
</dependency>
Verdent commented 2 months ago

fixed