[mkouba]

Yep, I understand. I meant if you tried to use some load/stress tool (jmeter, gatling) to simulate the problem...

[chrisjr]

No, but what could jmeter tell us about this issue anyway? It looks like there's some sequence of Tomcat thread usage that is leaving (possibly empty) bean stores lying around. And based on this morning's logs, my application code doesn't even need to be invoked first:

We shut our AWS instances down at night and relaunch them in the morning:

• May 13 06:03:46 myapp-ip-10-111-38-90cloud-init:May 13 05:03:38 cloud-init[2203]: util.py[DEBUG]: Read 13 bytes from /proc/uptime
• May 13 06:03:46 myapp-ip-10-111-38-90cloud-init:May 13 05:03:38 cloud-init[2203]: util.py[DEBUG]: cloud-init mode 'modules' took 60.695 seconds (60.70)
• May 13 06:50:16 myapp-ip-10-111-38-90dhclient:DHCPREQUEST on eth0 to 10.111.32.1 port 67 (xid=0x3687fd90)
• May 13 06:50:16 myapp-ip-10-111-38-90dhclient:DHCPACK from 10.111.32.1 (xid=0x3687fd90)
• May 13 06:50:17 myapp-ip-10-111-38-90dhclient:bound to 10.111.38.90 -- renewal in 1748 seconds.
• May 13 06:50:32 myapp-ip-10-111-38-90dhclient:DHCPREQUEST on eth0 to 10.111.32.1 port 67 (xid=0x58741cdb)
• May 13 06:50:32 myapp-ip-10-111-38-90dhclient:DHCPACK from 10.111.32.1 (xid=0x58741cdb)
• May 13 06:50:34 myapp-ip-10-111-38-90dhclient:bound to 10.111.38.90 -- renewal in 1355 seconds.
• May 13 07:03:47 myapp-ip-10-111-38-902015-05-13:06:03:46,257 [myapp-1.0.0-SNAPSHOT] [http-bio-8080-exec-1] [9d9d2b5a50bc9717.4824e10347591098<:40dd9c8fd73f70db] [Servlet] WARN: WELD-000714: HttpContextLifecycle guard leak detected. The Servlet container is not fully compliant. The value was 1
• May 13 07:03:47 myapp-ip-10-111-38-902015-05-13:06:03:46,258 [myapp-1.0.0-SNAPSHOT] [http-bio-8080-exec-1] [9d9d2b5a50bc9717.4824e10347591098<:40dd9c8fd73f70db] [Context] WARN: WELD-000225: Bean store leak was detected during org.jboss.weld.context.http.HttpRequestContextImpl association: org.apache.catalina.connector.Request@2114dbe8
• May 13 07:03:47 myapp-ip-10-111-38-902015-05-13:06:03:46,259 [myapp-1.0.0-SNAPSHOT] [http-bio-8080-exec-1] [9d9d2b5a50bc9717.4824e10347591098<:40dd9c8fd73f70db] [Context] WARN: WELD-000225: Bean store leak was detected during org.jboss.weld.context.http.HttpSessionContextImpl association: org.apache.catalina.connector.Request@2114dbe8
• May 13 07:03:47 myapp-ip-10-111-38-902015-05-13:06:03:46,280 [myapp-1.0.0-SNAPSHOT] [http-bio-8080-exec-1] [9d9d2b5a50bc9717.4824e10347591098<:40dd9c8fd73f70db] [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@2114dbe8

So the problem has happened once already, after the Tomcat had been up and idle for one hour. The only requests that have been received are HealthCheck requests (of which it receives one every 10 seconds from each of two different hosts), and possibly metrics requests although Librato is not currently enabled.

[chrisjr]

Having eliminated all of my application code, all that's really left is a few Filters and JAX-RS Providers. I've been reading up on the JAX-RS / CDI integration and I've realised that none of our @Provider classes is annotated as a bean (e.g. @ApplicationScoped). This is because they're imported from libraries, and not all of our applications use WELD. Unfortunately for me, my beans.xml is using bean-discovery-mode="annotated" and so these providers aren't being recognised as CDI beans. I've verified this by adding a new provider of my own:

@Provider
public class MyProvider implements ContainerRequestFilter, ContainerResponseFilter {
    private static final Logger LOG = LoggerFactory.getLogger(MyProvider.class);

    @PostConstruct
    void setup() {
        LOG.info(">>>> CREATING {}", toString());
    }

    @PreDestroy
    void done() {
        LOG.info(">>>> DESTROYING {}", toString());
    }

    @Override
    public void filter(ContainerRequestContext crc) throws IOException {
    }

    @Override
    public void filter(ContainerRequestContext crc, ContainerResponseContext crc1) throws IOException {
    }

}

Neither the @PostConstruct nor the @PreDestroy method is invoked unless I also add the @ApplicationScoped annotation.

The beans.xml doesn't seem to support an "include" directive - unless my schema is wrong?

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://xmlns.jcp.org/xml/ns/javaee"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/javaee http://xmlns.jcp.org/xml/ns/javaee/beans_1_1.xsd"
    bean-discovery-mode="annotated">
    <scan>
        <include name="my.company.MyProvider"/>
    </scan>
</beans>

Could the lack of a scope annotation on JAX-RS Providers be affecting things here?

I've added a beans.xml (bean-discovery-mode="all") to the library that provides this particular @Provider, and have verified that WELD is invoking its @PostConstruct and @PreDestroy methods. This is probably a Good Thing, regardless of whether it also resolves the WELD-000225 warnings(?).

[mkouba]

The beans.xml doesn't seem to support an "include" directive - unless my schema is wrong?

No it doesn't. There is an open spec issue to add include filters (CDI-526) but filters shouldn't be used to "add" something from the classpath but to specify what types from a bean archive should be scanned.

Could the lack of a scope annotation on JAX-RS Providers be affecting things here?

It depends on what these providers do. I mean the fact that they're not beans does not necessarily mean they're problematic. Do you have some info about what these providers are doing?

[chrisjr]

Do you have some info about what these providers are doing?

They're logging and metric filters, measuring how long requests to each different JAX-RS endpoint take.

[chrisjr]

OK, it's taken a while but I've finally managed to recreate the problem with a simple WAR - provided that WAR runs in Tomcat 7.0.59. (All my attempts to reproduce this while running Tomcat 7.0.57 have so far been unsuccessful).

I don't know exactly what it takes to trigger the problem either, but AWS does GET /api/health every 10 seconds from each of two remote hosts. And Nice Internet People repeatedly probing the server for URLs that do not exist appear to be very effective at it too.

More precisely: when someone does a GET for an unsupported URL, the following /api/health request is likely to trigger a WELD-000225 warning.

[mkouba]

I see. Do those "invalid" URLs target your REST API (i.e. /api/nonexisting)? I'm asking in order to determine the role of RESTEasy...

[chrisjr]

No, they're not directed at /api/* at all. They might be directed at the previous owner of this AWS IP address instead of being malicious, but they're a varied bunch:

2015-05-18 10:50:08,095 c=[10.111.90.143] "GET /nb/our-people/bolette-isholt-andersen HTTP/1.1" s=[404] S=[1025] d=[1ms]

2015-05-18 10:50:51,125 c=[10.111.90.143] "GET /living/whatsnew/2011-06-20-limericksconornilandqualifiesforwimbledontennischampionships HTTP/1.1" s=[404] S=[112

2015-05-18 10:51:19,148 c=[10.111.90.143] "GET /integratinglimerick/2015-02-17-magic-of-musicals HTTP/1.1" s=[404] S=[1047] d=[5ms]

etc...

[mkouba]

Chris,

still I wasn't able to reproduce the problem locally with Tomcat 7.0.62 and your simple WAR. I've limited the number of threads, made a lot of both GET with non-existent URL and GET /api/health requests and no warning appeared.  In any case, it doesn't look like a Weld issue.

[chrisjr]

Did you try with Tomcat 7.0.59? I haven't tested with Tomcat 7.0.62 since AWS doesn't provide those RPMs yet.

The JVM version that I'm using is:

# /usr/lib/jvm/java/bin/java -version

java version "1.7.0_71"

Java(TM) SE Runtime Environment (build 1.7.0_71-b14)

Java HotSpot(TM) 64-Bit Server VM (build 24.71-b01, mixed mode)

in case that affects things too.

[chrisjr]

Hmm: Tomcat bug 57824 looks "interesting"

Introduced as a regression in Tomcat 7.0.58, and fixed in Tomcat 7.0.62!

But in the meantime, AWS is providing Tomcat 7.0.59 RPMs...

[mkouba]

Yes, this might be the cause. Have you tried the proposed workaround, i.e. to declare an "universal" error page in web.xml?

[chrisjr]

Yes, I did. And it does appear to be an effective workaround. However, I've decided to revert to Tomcat 7.0.57 for now.

The only remaining question is whether this bug affects WELD 2.1.x as well as WELD 2.x? I haven't seen any log messages about "bean store leaks" with WELD 2.1.2.Final and Tomcat 7.0.59, but that might simply mean that the leak detection code is missing.

[mkouba]

The only remaining question is whether this bug affects WELD 2.1.x as well as WELD 2.x? I haven't seen any log messages about "bean store leaks" with WELD 2.1.2.Final and Tomcat 7.0.59, but that might simply mean that the leak detection code is missing.

Yes, I think it's affected and the detection code is missing. Moreover a fix for security issue WELD-1704 is not applied in 2.1 branch. You should not use 2.1.x as it is not actively developed anymore.

[chrisjr]

OK, thanks. We don't use @SessionScoped (we barely even use @RequestScoped) but it's good to know anyway.

I will use your email as leverage to (try and) stop people using WELD 2.0.4.Final too, while I'm at it. My curse on "Most Holy Generated POMs from the Dark Ages"...