WELD-000225 warning in Tomcat 7, but servlets are synchronous!

[chrisjr]

Hi,

My understanding of WELD-000225 is that Tomcat 7's implementation of asynchronous serlvets doesn't allow WELD to clean up correctly after an asynchronous request. I have therefore assumed that this implies a slow memory leak, and so I have configured all of my servlets as:

    <async-supported>false</async-supported>

However, I have still seen this warning in my Tomcat 7 log:

• May 07 13:53:58 <hostname> 2015-05-07:12:53:58,264 [app.version] [http-bio-8080-exec-25] [7f57d6ead72ebb1a.3b616bdd654ab187<:d6dcee4f46804ef3] [Servlet] WARN: WELD-000714: HttpContextLifecycle guard leak detected. The Servlet container is not fully compliant. The value was 1
• May 07 13:53:58 <hostname> 2015-05-07:12:53:58,265 [app.version] [http-bio-8080-exec-25] [7f57d6ead72ebb1a.3b616bdd654ab187<:d6dcee4f46804ef3] [Context] WARN: WELD-000225: Bean store leak was detected during org.jboss.weld.context.http.HttpRequestContextImpl association: org.apache.catalina.connector.Request@21a2331
• May 07 13:53:58 <hostname> 2015-05-07:12:53:58,265 [app.version] [http-bio-8080-exec-25] [7f57d6ead72ebb1a.3b616bdd654ab187<:d6dcee4f46804ef3] [Context] WARN: WELD-000225: Bean store leak was detected during org.jboss.weld.context.http.HttpSessionContextImpl association: org.apache.catalina.connector.Request@21a2331
• May 07 13:53:58 <hostname> 2015-05-07:12:53:58,274 [app.version] [http-bio-8080-exec-25] [7f57d6ead72ebb1a.3b616bdd654ab187<:d6dcee4f46804ef3] [Conversation] WARN: WELD-000335: Conversation context is already active, most likely it was not cleaned up properly during previous request processing: org.apache.catalina.connector.Request@21a2331

I am using WELD 2.2.11.Final, Resteasy 3.0.11.Final and Tomcat 7.0.59. Is there anything else I need to do please, apart from turn all the servlets' async-support off? My application doesn't use asynchronous servlets, so the incompatibilty with WELD doesn't bother me. But a potential memory leak does bother me.

Thanks,

Chris

P.S. The WELD FAQ only says "asynchronous servlets", but I've noticed that @javax.servlet.annotation.WebFilter has an asyncSupported attribute. Is this enough to trigger WELD-000225 please?

[mkouba]

Hi Chris,

could you provide more info about your application? E.g. what other technologies are used. We've also observed this kind of issue with server push technologies (see for example WELD-1704). Anyway, these warnings should not imply a memory leak in the sense that the information is always overwritten when the thread is reused by Weld.

[chrisjr]

Well, the technology stack is:

- WELD 2.2.11.Final

- Tomcat 7.0.59

- Resteasy 3.0.11.Final

- JDK7

- Logback 1.1.3

- Jackson 2.4.5

- Codahale metrics 3.0.2 with Librato servlet

- Hibernate Validator 5.1.3.Final

- Scala 2.9.2 (Don't ask! I don't want it, but can't remove it!)

(more or less). I don't use any asynchronous requests in my application, but I did find a couple of home-grown logging filters for urlPatterns="/*" which had been declared with asyncSupported=true. These seem (to me) to be likely candidates for these WELD-000225 warnings as they weren't accompanied by any other application-related log messages.

[chrisjr]

I disabled those filters' asynchronous support via web.xml, but am still seeing an occasional "Bean store leak" warning. So I'm out of ideas here.

Anyway, these warnings should not imply a memory leak in the sense that the information is always overwritten when the thread is reused by Weld.

To be clear: doesn't the bean store contains fully-constructed beans which have not had their @PreDestroy handlers etc invoked yet? Which would in turn imply that these beans will not be destroyed correctly when the thread-local variable is overwritten either.

BTW, if this forum is running on JBoss then it's a terrible JBoss advertisement...

[mkouba]

I disabled those filters' asynchronous support via web.xml, but am still seeing an occasional "Bean store leak" warning. So I'm out of ideas here.

AFAIK the only way to put the request into asynchronous mode is to call ServletRequest.startAsync(). So if you don't start async in your filter, it's not the cause. I see RESTEasy 3 in your stack. Do you use asynchronous processing capabilities in JAX-RS 2.0?

To be clear: doesn't the bean store contains fully-constructed beans which have not had their @PreDestroy handlers etc invoked yet? Which would in turn imply that these beans will not be destroyed correctly when the thread-local variable is overwritten either.

It depends on the scope of a bean. For @SessionScoped it shouldn't be a problem - bean instances are destroyed outside the servlet request lifecycle, during HttpSessionListener.sessionDestroyed() invocation. For @ConversationScoped this shouldn't be a problem either - conversation cleanup is performed for every request. Unfortunately, for @RequestScoped beans this is a problem and bean instances are not destroyed correctly.

BTW, if this forum is running on JBoss then it's a terrible JBoss advertisement...

http://developer.jboss.org uses Jive. Feel free to report a problem.

[chrisjr]

Do you use asynchronous processing capabilities in JAX-RS 2.0?

Not yet, no. But it's something I might want to use in the future. At the moment, all asynchronous work is done in ThreadPools created either by me or by the AWS SDK.

For @SessionScoped it shouldn't be a problem - bean instances are destroyed outside the servlet request lifecycle, during HttpSessionListener.sessionDestroyed() invocation. For @ConversationScoped this shouldn't be a problem either - conversation cleanup is performed for every request. Unfortunately, for @RequestScoped beans this is a problem and bean instances are not destroyed correctly.

Fortunately for me, all of my beans are either @Dependent, @Singleton or @ApplicationScoped. So hopefully these Bean Stores are all empty ...

[mkouba]

At the moment, all asynchronous work is done in ThreadPools created either by me or by the AWS SDK.

What async work?

[chrisjr]

What async work?

Submitting work to AWS, and waiting for SQS response messages in a separate thread. And on receiving a message, we start the next phase of processing.

We've previously had class-loader-like issues with WELD injections running from "non-container" / "user" threads (although I'm not sure why - I've found nothing in the CDI spec to explain it), and so our strategy is typically to create all of the beans up front and then launch our threads. However, we do appear to have the following code running in a user thread:

@Any Instance<ProcessingMethod> lookup;

...

Instance<ProcessingMethod> instance = lookup.select(new MethodNameQualifierLiteral(token));
ProcessingMethod method = instance.get();

The idea here is that we have a set of @ApplicationScoped ProcessingMethod beans, each with its own @MethodName qualifier. And when the SQS message arrives, we ask WELD to "look up" the correct processing method bean to peform the next processing step. But maybe the Instance.select() method is doing things with bean stores? (I have no idea what Instance.select() is doing "under the covers" - I just know that it's executing in a user thread rather than a Tomcat-started thread).

[mkouba]

I don't know much about AWS but if I understand it correctly you're not using async servlet API but doing the same using your own Tomcat/AWS specific stuff? If so then there is exactly the same problem as with async servlet API and Tomcat: ServletRequestListener.requestInitialized() callback is called from a different thread than the corresponding ServletRequestListener.requestDestroyed() callback. Note that Weld currently doesn't inspect the leaked bean store - so it may be empty. Maybe we should add a debug log message and write down some info about the beans found in the store.

With regard to non-container threads and CDI: within a user-controlled thread only application context (which is always active), singletons (which are not very well defined in CDI) and dependent pseudo-scope will work (see also Weld FAQ). All other built-in contexts must be activated/deactivated by the container. There are many parts of the spec which mention threads, e.g. 6.2. The Context interface:

At a particular point in the execution of the program a context object may be active with respect to the current thread.

or 6.3. Normal scopes and pseudo-scopes:

The context object for a normal scope type is a mapping from each contextual type with that scope to an instance of that contextual type. There may be no more than one mapped instance per contextual type per thread.

Instance.get() does work with bean stores because it tries to obtain a contextual reference for a selected bean.

[chrisjr]

but if I understand it correctly you're not using async servlet API but doing the same using your own Tomcat/AWS specific stuff?

Not quite. We don't use @RequestScoped beans at all, and allow the synchronous requests to end naturally. The asynchronous work is performed in the background by @ApplicationScoped and @Dependent beans.

With regard to non-container threads and CDI: within a user-controlled thread only application context (which is always active), singletons (which are not very well defined in CDI) and dependent pseudo-scope will work.

This is fine; we rarely use any other kind of bean anyway . I think our problems were more related to classes not being found when WELD tried to instantiate lazy proxies; it was very odd and happened with WELD 2.0.4.Final (I think). Getting WELD to inject everything before spawning new threads fixed the problem (i.e. "eager" vs "lazy" beans), and it's a practice we've stuck with ever since.

[chrisjr]

I tried replacing our Instance.select().get() code with a simple switch statement, but I'm still seeing WELD-000714 / WELD-000225 / WELD-000335 warnings. So it's not that either.

[mkouba]

I have no idea. It would be great if you could prepare a simplified application so that we could reproduce the issue locally.

[chrisjr]

When it comes to reproducing this issue, it seems only to be happening in AWS because my Tomcat in AWS is constantly receiving unrelated HTTP requests. E.g. the application has a RESTeasy "health check" handler which AWS is polling regularly:

@ValidateOnExecution
@ApplicationScoped
public class HealthCheckBean implements HealthCheck {

    @Override
    public Response health() {
        return Response.ok().build();
    }

}

@Path("/health")
public interface HealthCheck {

    @GET
    @HEAD
    Response health();

}

I think that it is these other handlers that are triggering the WELD-000225 warnings. (My AWS Tomcat was also just scanned for CGI scripts by some Nice Little Internet Person - that resulted in a lot of WELD-000225 warnings too!)

[mkouba]

I still don't see a reason why the health check should cause the warnings. Did you try to test the health check locally (gatling, jmeter)?

[chrisjr]

I'm not saying that every invocation of the health check triggers a WELD-000225 warning. I've simply compared the timestamps of the warnings with the timestamps in the localhost_access log and identified what the URLs were.