Search code examples
javajax-rsehcachehippocms

AlreadyCommittedException: Response already committed after doing buildPage but before writing response from PageInfo (HippoCMS)

We serve our CMS (Hippo) content using a REST endpoints, and I noticed strange behavior that happens intermittently:

Time and again, when invoking an end point (e.g., http://site.name/api/articles/) for the first time after a period of inactivity or server restart, it throws the following exception. If the page is refreshed second time, it all works.

Throwable thrown during doFilter on request with URI: /site/fr-ca/api/articles/ and Query: nullResponse already committed after doing buildPage but before writing response from PageInfo.
[INFO] [talledLocalContainer] net.sf.ehcache.constructs.web.AlreadyCommittedException: Response already committed after doing buildPage but before writing response from PageInfo.
[INFO] [talledLocalContainer]   at net.sf.ehcache.constructs.web.filter.CachingFilter.doFilter(CachingFilter.java:220)
[INFO] [talledLocalContainer]   at net.sf.ehcache.constructs.web.filter.Filter.doFilter(Filter.java:86)
[INFO] [talledLocalContainer]   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
[INFO] [talledLocalContainer]   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[INFO] [talledLocalContainer]   at org.hippoecm.hst.container.XSSUrlFilter.doFilter(XSSUrlFilter.java:52)
[INFO] [talledLocalContainer]   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
[INFO] [talledLocalContainer]   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[INFO] [talledLocalContainer]   at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
[INFO] [talledLocalContainer]   at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
[INFO] [talledLocalContainer]   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
[INFO] [talledLocalContainer]   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[INFO] [talledLocalContainer]   at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
[INFO] [talledLocalContainer]   at org.apache.catalina.core.StandardContextValve.__invoke(StandardContextValve.java:106)
[INFO] [talledLocalContainer]   at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java)
[INFO] [talledLocalContainer]   at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
[INFO] [talledLocalContainer]   at org.apache.catalina.core.StandardHostValve.__invoke(StandardHostValve.java:142)
[INFO] [talledLocalContainer]   at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java)
[INFO] [talledLocalContainer]   at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
[INFO] [talledLocalContainer]   at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:617)
[INFO] [talledLocalContainer]   at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
[INFO] [talledLocalContainer]   at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
[INFO] [talledLocalContainer]   at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)
[INFO] [talledLocalContainer]   at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:668)
[INFO] [talledLocalContainer]   at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1521)
[INFO] [talledLocalContainer]   at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1478)
[INFO] [talledLocalContainer]   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[INFO] [talledLocalContainer]   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[INFO] [talledLocalContainer]   at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
[INFO] [talledLocalContainer]   at java.lang.Thread.run(Thread.java:745)

where the culprit code is given below:

protected void doFilter(final HttpServletRequest request,
        final HttpServletResponse response, final FilterChain chain)
        throws AlreadyGzippedException, AlreadyCommittedException,
        FilterNonReentrantException, LockTimeoutException, Exception {
    if (response.isCommitted()) {
        throw new AlreadyCommittedException(
                "Response already committed before doing buildPage.");
    }
    logRequestHeaders(request);
    PageInfo pageInfo = buildPageInfo(request, response, chain);

    if (pageInfo.isOk()) {
        if (response.isCommitted()) {
            throw new AlreadyCommittedException(
                    "Response already committed after doing buildPage"
                            + " but before writing response from PageInfo.");
        }
        writeResponse(request, response, pageInfo);
    }
}

Line 220 is the one that throws AlreadyCommittedException() inside the if(response.isCommitted()) {},

which makes me think the server thinks at this point the response is already committed. I have checked my code and I can confirm I do not do any "in-between" commits or writing to the servlet's output stream.

But what's most annoying, it only happens on the first page call, and if I refresh the page the problem is gone.

Additional detail: we have a caching filter that caches a page and invokes the CacheFilter:

public class WaPageCache extends SimpleCachingHeadersPageCachingFilter {

    @Override
    protected String calculateKey(HttpServletRequest httpRequest) {
        String simpleKey = super.calculateKey(httpRequest);
        final String requestURI = httpRequest.getRequestURI();
        final String key = requestURI.contains("/binaries/content") ? simpleKey : simpleKey + httpRequest.getHeader("Cookie");
        return key;
    }

    @Override
    protected CacheManager getCacheManager() {
        ClassLoader standardClassloader = Thread.currentThread().getContextClassLoader();
        URL url = null;
        if (standardClassloader != null) {
            url = standardClassloader.getResource("ehcache-web-caching.xml");
        }
        return CacheManager.create(url);
    }
}

Has anyone else fought similar problem and what are the possible causes/solutions/hints on solution?

Solution

  • I've found a fix: in my webapp, I have several filters, and the trick was to put the caching filter after all other ones (in my, Hippo case, specifically after the HstFilter). Well, I've got another filter that sets response headers, and that one is ok to go after the caching filter. Here's a fragment of my updated web.xml:

          <filter-mapping>
        <filter-name>HstFilter</filter-name>
        <url-pattern>/*</url-pattern>
      </filter-mapping>

      <!-- This is my filter that was throwing the spanner -->
      <filter-mapping> 
        <filter-name>WaPageCache</filter-name>
        <url-pattern>/*</url-pattern>
      </filter-mapping>

      <filter-mapping>
        <filter-name>ApiResourceHeadersFilter</filter-name>
        <url-pattern>/api/site/*</url-pattern>
      </filter-mapping>