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

[Nestor Milyaev]

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 throw new 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?

[Woonsan Ko]

Hi Nestor,

I guess you put the caching servlet filter before HstFilter to cache the responses.

I don't exactly why the response was committed when HST doesn't write anything yet at the moment, but it is sometimes tricky because your caching filter (or its base filter) could write anything in prior *or* the response data might be loaded from a (disk) cached item having a wrong(?) committed status data as well..

Anyway, if you handle response caching by yourself, it's very hard for us to give advice.

By the way, do you know that you can use HST Page Caching [1] for REST pipelines too?

In v11, it is just a matter of enabling the page cache in the rest mount, but in v10, you need to customize the rest pipeline to add two additional valves as mentioned in [2].

If you can use HST Page Caching for your rest services, then it should probably be working fine, I guess.

HTH,

Woonsan

[1] https://www.onehippo.org/10/library/concepts/request-handling/hst-page-caching.html

[2] https://issues.onehippo.com/browse/HSTTWO-3622

LifeWorks - The Employee Engagement Platform

Download our App! Available on iOS | Android | Web

---

Registered in UK: 08223675
This communication is intended to be received only by the individual[s] or entity[s] to whom or to which it is addressed, and contains information which is confidential, privileged and subject to copyright. Any unauthorised use, copying, review or disclosure is prohibited. Please notify the sender immediately if you have received this communication in error [by calling collect, if necessary] so that we can arrange for its return at our expense. Thank you in advance for your anticipated assistance and cooperation.

--
Hippo Community Group: The place for all discussions and announcements about Hippo CMS (and HST, repository etc. etc.)
 
To post to this group, send email to hippo-community@googlegroups.com
RSS: https://groups.google.com/group/hippo-community/feed/rss_v2_0_msgs.xml?num=50
---
You received this message because you are subscribed to the Google Groups "Hippo Community" group.
To unsubscribe from this group and stop receiving emails from it, send an email to hippo-community+unsubscribe@googlegroups.com.
Visit this group at https://groups.google.com/group/hippo-community.
For more options, visit https://groups.google.com/d/optout.

--

w....@onehippo.com     www.onehippo.com
Boston - 745 Atlantic Ave, 8th Floor, Boston MA 02111
Amsterdam - Oosteinde 11, 1017 WT Amsterdam
US +1 877 414 4776 (toll free)
Europe +31(0)20 522 4466

[Nestor Milyaev]

Thank you very much Woosan,

That is helpful. I'll test this properly on Tuesday (monday is holiday in England).

Best regards,

Nestor

-- Hippo Community Group: The place for all discussions and announcements about Hippo CMS (and HST, repository etc. etc.)   To post to this group, send email to hippo-c...@googlegroups.com RSS: https://groups.google.com/group/hippo-community/feed/rss_v2_0_msgs.xml?num=50 --- You received this message because you are subscribed to a topic in the Google Groups "Hippo Community" group. To unsubscribe from this topic, visit https://groups.google.com/d/topic/hippo-community/OjyuLYyr3mo/unsubscribe. To unsubscribe from this group and all its topics, send an email to hippo-communi...@googlegroups.com. Visit this group at https://groups.google.com/group/hippo-community. For more options, visit https://groups.google.com/d/optout.

-- 



Nestor Milyaev
Java Developer

1 Battersea Bridge Road, London SW11 3BZ

T: +44 20 3567 5900 | E: nestor....@lifeworks.com

[Ard Schrijvers]

Hey Nestor,

did you look at [1]. That already uses some ehcache web caching logic. In general you can better not set a caching filter in front of the hst filter (if you want that, then you can also just use mod_cache, squid, nginx, etc on proxy level before the container)

HTH,

Regards Ard

ps note 11.1 will most likely ship with some very nice new caching features (next to what we already have with stampeding herd protection, also stale page response support and second level caching which can be cluster wide). Also [1] works seamlessly with our relevance (personalization) 

[1] https://www.onehippo.org/library/concepts/request-handling/hst-page-caching.html

-- Hippo Community Group: The place for all discussions and announcements about Hippo CMS (and HST, repository etc. etc.)   To post to this group, send email to hippo-community@googlegroups.com RSS: https://groups.google.com/group/hippo-community/feed/rss_v2_0_msgs.xml?num=50 --- You received this message because you are subscribed to a topic in the Google Groups "Hippo Community" group. To unsubscribe from this topic, visit https://groups.google.com/d/topic/hippo-community/OjyuLYyr3mo/unsubscribe. To unsubscribe from this group and all its topics, send an email to hippo-community+unsubscribe@googlegroups.com. Visit this group at https://groups.google.com/group/hippo-community. For more options, visit https://groups.google.com/d/optout.

-- 



Nestor Milyaev
Java Developer

1 Battersea Bridge Road, London SW11 3BZ

T: +44 20 3567 5900 | E: nestor....@lifeworks.com

LifeWorks - The Employee Engagement Platform

Download our App! Available on iOS | Android | Web

---

Registered in UK: 08223675
This communication is intended to be received only by the individual[s] or entity[s] to whom or to which it is addressed, and contains information which is confidential, privileged and subject to copyright. Any unauthorised use, copying, review or disclosure is prohibited. Please notify the sender immediately if you have received this communication in error [by calling collect, if necessary] so that we can arrange for its return at our expense. Thank you in advance for your anticipated assistance and cooperation.

--

Hippo Community Group: The place for all discussions and announcements about Hippo CMS (and HST, repository etc. etc.)
 
To post to this group, send email to hippo-community@googlegroups.com
RSS: https://groups.google.com/group/hippo-community/feed/rss_v2_0_msgs.xml?num=50
---
You received this message because you are subscribed to the Google Groups "Hippo Community" group.
To unsubscribe from this group and stop receiving emails from it, send an email to hippo-community+unsubscribe@googlegroups.com.
Visit this group at https://groups.google.com/group/hippo-community.
For more options, visit https://groups.google.com/d/optout.

--

Hippo Netherlands, Oosteinde 11, 1017 WT Amsterdam, Netherlands
Hippo USA, Inc. 71 Summer Street, 2nd Floor Boston, MA 02110, United states of America.

US +1 877 414 4776 (toll free)
Europe +31(0)20 522 4466

www.onehippo.com

[Nestor Milyaev]

Thank you Ard,

I'll have a look - and both yours and Woosan's email make me think that
perhaps upgrade to v.11 needs to be done asap.

Best regards,

Nestor

On 25/08/16 18:08, Ard Schrijvers wrote:
> Hey Nestor,
>
> did you look at [1]. That already uses some ehcache web caching logic.
> In general you can better not set a caching filter in front of the hst
> filter (if you want that, then you can also just use mod_cache, squid,
> nginx, etc on proxy level before the container)
>
> HTH,
>
> Regards Ard
>
> ps note 11.1 will most likely ship with some very nice new caching
> features (next to what we already have with stampeding herd
> protection, also stale page response support and second level caching
> which can be cluster wide). Also [1] works seamlessly with our
> relevance (personalization)
>
> [1]
> https://www.onehippo.org/library/concepts/request-handling/hst-page-caching.html

--

LifeWorks - The Employee Engagement Platform

Download our App! Available on iOS

<https://itunes.apple.com/gb/app/workangel/id662088737> | Android
<https://play.google.com/store/apps/details?id=com.wam.android> | Web
<https://app.workangel.com>
------------------------------

[Ard Schrijvers]

On Fri, Aug 26, 2016 at 10:43 AM, Nestor Milyaev
<nestor....@lifeworks.com> wrote:
> Thank you Ard,
>
> I'll have a look - and both yours and Woosan's email make me think that
> perhaps upgrade to v.11 needs to be done asap.

The HST page cache is already available since IIRC version 7.8 (or
7.9), so you can just use it!

In 11.1 I just want to get in some really nice enhancements (which I
think really are awesome....seriously...only downside is that you
shouldn't say that about your own work, but I really think the 'first
level page cache with stampeding herd protection + second level
(optionally cluster wide) page cache + stale page response support
working nicely with the stampeding herd (the herd gets the stale page,
only one person waiting for the new non-stale page to be build)' is
quite amazing, certainly since the second level cache will be a
plugable spring wired cache (default redis, but can choose for
different caches (and different redis clients). Note that the shared
cache will be also very usable for non-page-caching (think about
expensive rest calls to external systems that you want to cache in the
application...that still means every cluster node would have to do
this expensive external call at least once, unless you also store the
response in the second level cluster wide cache). Either way, now I
stop. You can use the page cache already before version 11

HTH<

Regards Ard

> --
> Hippo Community Group: The place for all discussions and announcements about
> Hippo CMS (and HST, repository etc. etc.)
>

> To post to this group, send email to hippo-c...@googlegroups.com

> RSS:
> https://groups.google.com/group/hippo-community/feed/rss_v2_0_msgs.xml?num=50
> --- You received this message because you are subscribed to the Google
> Groups "Hippo Community" group.
> To unsubscribe from this group and stop receiving emails from it, send an

> email to hippo-communi...@googlegroups.com.

[Nestor Milyaev]

Ard, Woosan,

Thank you so much guys for your help.

Putting the cacheFilter after HST one really did the trick - an easy fix!
It all seems to be working now. I'll look specifically into HST page cache later on when I have more time and I'm quite curious to try the v.11 cache as well - once we update to that version.

Best regards,
Nestor