Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
vamseeds opened this issue Jul 2, 2024 · 3 comments
Assignees
Labels
4.x Version 4.x bug Something isn't working logging P2

Comments

@vamseeds
Copy link

vamseeds commented Jul 2, 2024

Environment Details

  • Helidon Version: 4.0.9
  • Helidon SE
  • JDK version: 21
  • OS: Mac
  • Docker version (if applicable): NA

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
Copy link
Member

Verdent commented Jul 2, 2024

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 Verdent self-assigned this Jul 2, 2024
@Verdent Verdent added bug Something isn't working logging 4.x Version 4.x labels Jul 2, 2024
@m0mus m0mus added the P2 label Jul 8, 2024
@Verdent
Copy link
Member

Verdent commented Jul 11, 2024

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
Copy link
Member

Verdent commented Jul 24, 2024

fixed

@Verdent Verdent closed this as completed Jul 24, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
4.x Version 4.x bug Something isn't working logging P2
Projects
Archived in project
Development

No branches or pull requests

3 participants