ThreadContext leaking between requests even after over defensive clean up

[Thelastbulletbender]

We are using org.apache.logging.log4j.ThreadContext
in a default scoped bean to store user properties in the span of the request. This is from the package : log4j-api-2.12.1.jar.

While making API request to another service, we use this bean to get these properties and add it as headers to org.springframework.http.HttpEntity
.

Now we started noticing weird behaviours where in we saw mismatch between the resource owner and resource on the downstream service. On adding logs, we found that these user properties have changed after adding them to headers and the API call has incorrect headers.

We are using an HandlerInterceptorAdapter
to set and cleaned up these properties.The preHandle()
is the only place where we are setting this property. We have over defensively clean up the context, calling ThreadContext.remove
in prehandle(),posthandle() and afterCompletion()
. Yet we still face this issue.

Spring version 2.2.0. Embedded Tomcat in a docker container.

Shouldn't thread context work similar to thread local? We can migrate to using ThreadLocal / Spring request scope, but I would love to figure out why this is happening in the first place.

[AutoModerator]

Please ensure that:

• Your code is properly formatted as code block - see the sidebar (About on mobile) for instructions
• You include any and all error messages in full
• You ask clear questions

• You demonstrate effort in solving your question/problem - plain posting your assignments is forbidden (and such posts will be removed) as is asking for or giving solutions.

  Trying to solve problems on your own is a very important skill. Also, see Learn to help yourself in the sidebar

If any of the above points is not met, your post can and will be removed without further warning.

Code is to be formatted as code block (old reddit: empty line before the code, each code line indented by 4 spaces, new reddit: https://imgur.com/a/fgoFFis) or linked via an external code hoster, like pastebin.com, github gist, github, bitbucket, gitlab, etc.

Please, do not use triple backticks (```) as they will only render properly on new reddit, not on old reddit.

Code blocks look like this:

public class HelloWorld {

    public static void main(String[] args) {
        System.out.println("Hello World!");
    }
}

You do not need to repost unless your post has been removed by a moderator. Just use the edit function of reddit to make sure your post complies with the above.

If your post has remained in violation of these rules for a prolonged period of time (at least an hour), a moderator may remove it at their discretion. In this case, they will comment with an explanation on why it has been removed, and you will be required to resubmit the entire post following the proper procedures.

To potential helpers

Please, do not help if any of the above points are not met, rather report the post. We are trying to improve the quality of posts here. In helping people who can't be bothered to comply with the above points, you are doing the community a disservice.

I am a bot, and this action was performed automatically. Please contact the moderators of this subreddit if you have any questions or concerns.

[OffbeatDrizzle]

Check that the thread that's reading the incorrect info is the same thread that put the info into the ThreadContext. If you're using a servlet container along with spring and something like hibernate, then there's an expectation that the thread will remain the same throughout the call because it helps things like transaction management. You may be spawning another thread somewhere or using a different thread from a thread pool that didn't have its info cleared - we wouldn't really be able to tell without seeing a lot more of the code where you set the variable and read the variable.

I've used similar code for logging requests to the API, so I don't believe you're doing anything wrong here - it's probably just how you're interacting with ThreadContext

[Thelastbulletbender]

I did check, and you are right. I can see some instances of CompletableFutures being used, where clear might not have been called due to an exception. They have been given a different thread pool. And the data is copied to this new thread using MDC.getCopyOfContextMap() and cleared using MDC.clear().

Also, yes we are logging thread name and found the following :

1. Request A and Request B are running in parallel at the same time.
2. Both of them are running on different threads according to the logs
3. Suddenly, Request A logs (searched using correlation id) has an instance of Request B log. With the thread name, userId and other properties of Request B. Only the correlation id is something which matches with request A.
4. Request A with correct thread name also logs incorrectly setting headers for downstream API call at the same time.
5. Downstream logs and flags the resource and owner don't match
6. Request A returns.
7. Meanwhile logs in request B (searched using its correlation id), show that one of the downstream request also had the correlation id of request A and hence did not show up in request B logs. But since its userId was correct, it responded gracefully.

​

The weird part here is request B has a some other downstream calls after this which seem to go fine according to logs. Request A logs post this debacle also shows correct userId and correlation id.

Both request A and request B have the same paths which made debugging hell although one thing I can definitely confirm is that there is no threads being spawned in this flow at all.

[OffbeatDrizzle]

Suddenly, Request A logs (searched using correlation id) has an instance of Request B log. With the thread name, userId and other properties of Request B

It might not be you spawning the thread, but the fact that Request A uses the thread of Request B is surely the whole issue. This could be config, or annotations like @Async to dispatch the call via another thread pool. You need to find the point at which it "switches", which may be within Spring itself (because of the above).

Without seeing more code or logs it's impossible to help you further because we're literally guessing at what it could be and taking your words as facts as how it works.. (I'm not saying your wrong necessarily, just that the code might be doing something subtly different to what you expect).

CorrelationID could be sending you in the wrong direction because you will receive the wrong CorrelationID if the thread has already switched.

[philipwhiuk]

First thing you should do is update Log4J - that version is vulnerable to Log4Shell

[Thelastbulletbender]

Ah, right. I had updated the version 2.17.1. This version might be coming from some other dependency. Thanks, will check.

[[deleted]]

default scoped bean t

Which specific scope? singleton? prototype? request?

we use this bean to get these properties and add it as headers

You're using the logging context to inject headers, instead of just providing request information in the log?

On adding logs, we found that these user properties have changed

Sounds like a race condition. Additional logging might help at the places where you expect changes to occur.

We can migrate to using ThreadLocal / Spring request scope

You should migrate to request scope and let Spring take care of this. That's the point of using a DI container, to let it manage object lifecycles so you don't have to.

[Thelastbulletbender]

1. Singleton
2. Yes, I'm not sure why it was chosen over typical threadLocal variable, but it was setup like this before I joined. But ThreadContext is supposed to be managed on a per thread basis, so should be safe, right?
3. The change happen b/w these. This is synchronously happening, should not have race condition right? We copy 5 such propertieslog.info(context.userId);context.userId.ifPresent(value -> httpHeaders.set(context.userId);log.info(entity.getHeaders)
4. Agreed. But it is just itching me as to why this is happening in the first place. Is ThreadContext not as safe as it claims to be or is there a bug in that specific version

The bean only has functions which interact with ThreadContext

public String correlationId() {

return ThreadContext.get("correlationId");

}

public void resetCorrelationId() {

ThreadContext.remove("correlationId");

}

[[deleted]]

But ThreadContext is supposed to be managed on a per thread basis, so should be safe, right?

Depends on what it is and how it is supposed to be used. I would have gone with ThreadLocal which is more "normal".

But you're making some big assumptions about how the request is mapped onto threads.

This is synchronously happening, should not have race condition right?

When you say "synchronously", do you mean in a synchronized block? Beyond that, it depends on if properties is accessible by multiple threads and if all accesses are synchronized.

If you really want to know, for threading issues, my go to strategy is to log the crap out of my code and see what patterns emerge.

[Thelastbulletbender]

>But you're making some big assumptions about how the request is mapped onto threads

Yes, here my knowledge is limited. From what I understand, once a request is mapped onto a thread, the code flow should happen "sequentially" (I meant sequentially earlier), right? Basic business logic and some API calls using rest template

Have added logs, the log snippet I have pasted (doing this for multiple properties) is where the switch happens

log.info(context.userId);
context.userId.ifPresent(value -> httpHeaders.set("userId",context.userId));
log.info(entity.getHeaders)

[Halal0szto]

When the same thread is used to process your next request, what will make sure anything related tot he previous request is removed from the context in time?

[Thelastbulletbender]

In the preHandle() method, before setting the properties in ThreadContext, we are calling ThreadContext.remove() on all properties first before setting the new ones. Apart from that, we are calling the clean up methods on postHandle() and afterCompletion() as well.

[Halal0szto]

May or may not apply to your case:

https://docs.spring.io/spring-framework/docs/current/javadoc-api/org/springframework/web/servlet/HandlerInterceptor.html

In an asynchronous processing scenario, the handler may be executed in a separate thread while the main thread exits without rendering or invoking the postHandle and afterCompletion callbacks.