Using ContextLocals: Issue when running non-API related JUnit tests

[christosperis]

Hi,

We are developing some API Gateway app/units that perform the following:

1. Receives incoming requests on RESTEasy REST APIs.
2. Filters request using ContainerRequestContext and populates the request related context using ContextLocals.
3. Perform some processing and checks on the received requests.
4. Forward the requests to a destination component, as a REST Client.

We are using io.smallrye.common.vertx.ContextLocals for context propagation purposes, mainly for propagating incoming REST request related attributes (i.e. header values) throughout execution flow of this request.

Additionally:

• Our RESTEasy APIs are blocking (non Uni, Multi return types)
• We use client filters (ClientRequestFilter, ClientResponseFilter) for logging outbound requests, inbound responses, where our app is client towards other services.

The issue we face is taking place when running some specific JUnit QuarkusTests, whose execution flow doesn't include RESTEasy related invocation, but do invoke the rest client directly.

We are attaching a sample quarkus project, that reproduce s the issue.
contextlocals-tests-reproduce.zip

The app features a sample Resource API, and two JUnit tests. One API related, and one invoking a rest client directly. The destination is a mocked endpoint.

We have also included a logging point in the Client Filter indicating whether it's on duplicated context or not.

Here are the steps:

1. Run the application and perform a curl to /hello/greet endpoint:

curl --request GET \
  --url http://localhost:8080/hello/greet \
  --header 'correlationId: 59a9bb00-ceb0-408e-8217-45b31b96d230' 

===========REGULAR API REQUEST RUNTIME EXECUTION FLOW====================
a. API triggered flow is delegated on a worker thread - (context runs on duplicatedContext)
b. ClientRequestContext filter runs on worker thread - (context runs on duplicatedContext)
c. ClientResponseContext filter runs on eventloop thread - (context runs on duplicatedContext)

2023-06-21 17:45:05.270  Quarkus Main Thread -  INFO  io.quarkus code-with-quarkus 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.15.3.Final) started in 2.501s. Listening on: http://localhost:8080
2023-06-21 17:45:05.275  Quarkus Main Thread -  INFO  io.quarkus Profile dev activated. Live Coding activated.
2023-06-21 17:45:05.277  Quarkus Main Thread -  INFO  io.quarkus Installed features: [cdi, rest-client-reactive, rest-client-reactive-jackson, resteasy-reactive, resteasy-reactive-jackson, scheduler, smallrye-context-propagation, vertx]
2023-06-21 17:45:10.177  executor-thread-0 -  INFO  org.acme.filter.ServerLoggingFilter cd3ac1f3-c401-45d8-9d1d-f277dc5e3bb1 - Received HTTP request: GET /hello/greet
2023-06-21 17:45:10.227  executor-thread-0 -  INFO  org.acme.resource.GreetingResource Inside Greeting Blocking Resource - The correlationId is: cd3ac1f3-c401-45d8-9d1d-f277dc5e3bb1
2023-06-21 17:45:10.244  executor-thread-0 -  INFO  org.acme.filter.ClientLoggingFilter Client request filter is on duplicated context: true
2023-06-21 17:45:10.250  executor-thread-0 -  INFO  org.acme.filter.ClientLoggingFilter cd3ac1f3-c401-45d8-9d1d-f277dc5e3bb1 - Sent HTTP request: GET http://localhost:8080/mockServer/mock
2023-06-21 17:45:10.324  executor-thread-1 -  INFO  org.acme.resource.MockServerResource Inside Mock server Resource - The correlationId is: null
2023-06-21 17:45:10.364  vert.x-eventloop-thread-1 -  INFO  org.acme.filter.ClientLoggingFilter Client response filter is on duplicated context: true
2023-06-21 17:45:10.365  vert.x-eventloop-thread-1 -  INFO  org.acme.filter.ClientLoggingFilter cd3ac1f3-c401-45d8-9d1d-f277dc5e3bb1 - Received HTTP response: GET http://localhost:8080/mockServer/mock
2023-06-21 17:45:10.371  executor-thread-0 -  INFO  org.acme.filter.ServerLoggingFilter cd3ac1f3-c401-45d8-9d1d-f277dc5e3bb1 - Sent HTTP response: GET /hello/greet

===========REGULAR RUNTIME EXECUTION FLOW====================

In the above, context propagation works fine, and all the flow runs on duplicatedContext.

2. Run the API related JUnit test named testRequestBasedFlow:

===========API TEST EXECUTION FLOW====================
a. QuarkusTest execution is delegated on a worker thread (context runs on duplicatedContext)
b. ClientRequestContext filter runs on worker thread - (context runs on duplicatedContext)
c. ClientResponseContext filter runs on eventloop thread - (context runs on duplicatedContext)
d. Test passes

2023-06-21 17:41:44.159  main -  INFO  io.quarkus.scheduler.runtime.SimpleScheduler Simple scheduler is disabled by config property and will not be started
2023-06-21 17:41:44.303  main -  INFO  io.quarkus code-with-quarkus 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.15.3.Final) started in 2.524s. Listening on: http://localhost:8081
2023-06-21 17:41:44.304  main -  INFO  io.quarkus Profile test activated. 
2023-06-21 17:41:44.304  main -  INFO  io.quarkus Installed features: [cdi, rest-client-reactive, rest-client-reactive-jackson, resteasy-reactive, resteasy-reactive-jackson, scheduler, smallrye-context-propagation, vertx]
2023-06-21 17:41:45.874  executor-thread-0 -  INFO  org.acme.filter.ServerLoggingFilter 7894261b-5b80-4023-91eb-ac0944311c22 - Received HTTP request: GET /hello/greet
2023-06-21 17:41:45.877  executor-thread-0 -  INFO  org.acme.resource.GreetingResource Inside Greeting Blocking Resource - The correlationId is: 7894261b-5b80-4023-91eb-ac0944311c22
2023-06-21 17:41:45.890  executor-thread-0 -  INFO  org.acme.filter.ClientLoggingFilter Client request filter is on duplicated context: true
2023-06-21 17:41:45.891  executor-thread-0 -  INFO  org.acme.filter.ClientLoggingFilter 7894261b-5b80-4023-91eb-ac0944311c22 - Sent HTTP request: GET http://localhost:8081/mockServer/mock
2023-06-21 17:41:45.985  executor-thread-1 -  INFO  org.acme.resource.MockServerResource Inside Mock server Resource - The correlationId is: null
2023-06-21 17:41:46.010  vert.x-eventloop-thread-0 -  INFO  org.acme.filter.ClientLoggingFilter Client response filter is on duplicated context: true
2023-06-21 17:41:46.011  vert.x-eventloop-thread-0 -  INFO  org.acme.filter.ClientLoggingFilter 7894261b-5b80-4023-91eb-ac0944311c22 - Received HTTP response: GET http://localhost:8081/mockServer/mock
2023-06-21 17:41:46.203  main -  INFO  io.quarkus code-with-quarkus stopped in 0.065s

===========TEST EXECUTION FLOW====================

In the above, context propagation works fine, and all the flow runs on duplicatedContext.

3. Run the non-API related JUnit test named testRestClientDirectly:

===========Direct client invocation TEST EXECUTION FLOW====================
a. QuarkusTest is starting on a "main" (Junit) thread - VertxContext.isOnDuplicatedContext()==false(context on root context))
b. ClientRequestContext filter runs on main thread - VertxContext.isOnDuplicatedContext() (context on root context))
c. Exception is thrown: java.lang.UnsupportedOperationException: Access to Context Locals are forbidden from a 'root' context as it can leak data between unrelated processing. Make sure the method runs on a 'duplicated' (local) Context

2023-06-21 17:44:09.863  main -  INFO  io.quarkus.scheduler.runtime.SimpleScheduler Simple scheduler is disabled by config property and will not be started
2023-06-21 17:44:09.987  main -  INFO  io.quarkus code-with-quarkus 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.15.3.Final) started in 2.793s. Listening on: http://localhost:8081
2023-06-21 17:44:09.989  main -  INFO  io.quarkus Profile test activated. 
2023-06-21 17:44:09.989  main -  INFO  io.quarkus Installed features: [cdi, rest-client-reactive, rest-client-reactive-jackson, resteasy-reactive, resteasy-reactive-jackson, scheduler, smallrye-context-propagation, vertx]
2023-06-21 17:44:10.728  main -  INFO  org.acme.filter.ClientLoggingFilter Client request filter is on duplicated context: false
2023-06-21 17:44:10.737  main -  INFO  org.acme.filter.ClientLoggingFilter Client response filter is on duplicated context: false

java.lang.UnsupportedOperationException: Access to Context Locals are forbidden from a 'root' context  as it can leak data between unrelated processing. Make sure the method runs on a 'duplicated' (local) Context

===========TEST EXECUTION FLOW====================

In the above, the flow is starting from JUnit's main thread and flow runs on root context.

Long story short: it seems that when a processing unit isn't triggered through a RESTEasy API, Vert.x is unable to run the execution on duplicatedContext.
We came across @io.quarkus.test.vertx.RunOnVertxContext , however this is effective in reactive, non-blocking APIs, which isn't our case. Is there a workaround for such test cases that would ultimately guide Vert.x to run on duplicated context?

We are on Quarkus 2.15.3.Final, and Java 11. Thanks in advance!

[geoand]

Thanks for the thorough report!

I think I have understood what you want and if so, #34245 is the solution :)

[christosperis]

Absolutely stunned from the instant reponse and handling! Really grateful!

One note: Observing the MR, we saw that the fix is actually ensuring that the ClientRequestFilter is being invoked on the duplicated context: https://github.com/quarkusio/quarkus/pull/34245/files#diff-49402dd8ab3d397424802ef9276e95ce0650c81f261a03a3593402843d4bac5eR26 .

Will it also be the case for ClientReponseFilters? Shall we also add a relevant case in CorrelationIdClient interface, for a ClientResponseFilter interacting with ContextLocals, so that we ensure that when the response is filtered, it will also be ran onto duplicated context and not root?

[geoand]

Yeah, everything should not be executed on the proper context

[haruccigr]

So, after the solution is merged we would be able to use @io.quarkus.test.vertx.RunOnVertxContext with blocking code which is a very nice feature. Fooling around with @RunOnVertxContext and reactive rest clients I saw that a @org.junit.jupiter.params.ParameterizedTest does not work with @RunOnVertxContext, because the parameters are not resolved successfully.

More specifically, this:

  @RunOnVertxContext
  @ParameterizedTest
  @ValueSource(strings = {"harry", "jim"})
  void test(String name, UniAsserter uniAsserter) {
    uniAsserter.execute(() -> System.out.println(name));
  }

Throws NPE because the uniAsserter is null after the parameters are resolved.

And also the following has the same behaviour:

  private static Stream<Arguments> getParams() {
    return Stream.of(
      Arguments.of("harry"),
      Arguments.of("jim")
    );
  }
  
   @RunOnVertxContext
  @ParameterizedTest
  @MethodSource("getParams")
  void test(String name, UniAsserter uniAsserter) {
    uniAsserter.execute(() -> System.out.println(name));
  }

I have also tried to put the UniAsserter as the first argument, however it seems that Junit tries to map the Source values to the UniAsserter object.

So, question: is @RunOnVertxContext compatible with @ParameterizedTest? From what I understand it should be fully compatible with Junit5.

Thanking in advance,
Harry

[geoand]

Unfortunately it is not compatible with ParametrizedTest.

We could perhaps make it work, but it would likely be a large effort full of hacks

[leslion]

Hi,

I have the exact same scenario as described here, having issues running parameterized tests.

Is there an upcoming fix for the incompatibility between @RunOnVertxContext and @ParameterizedTest?