users@glassfish.java.net

[gf-users] Re: Using AJP when downloading of large streaming data results in the errors "OutOfMemoryError: Java heap space" and "503 Service Temporarily Unavailable"

From: Philip Durbin <philipdurbin_at_gmail.com>
Date: Wed, 1 Jul 2015 15:02:22 -0400

Update: the OutOfMemoryError when using AJP problem was fixed in
commit* 102c432aa2004c581db1c297e94b0eb90dd74122 yesterday in
https://java.net/jira/browse/GRIZZLY-1787 which added this line:

cachedResponse.setChunkingAllowed(true);

The fix version is Grizzly 2.3.22. Will this be included in Glassfish 4.2?

Phil

* https://java.net/projects/grizzly/sources/git/diff/modules/http-ajp/src/main/java/org/glassfish/grizzly/http/ajp/AjpHttpRequest.java?rev1=e9ea48db1b28405885d666475ba0d0c2f1abdcc4&rev2=102c432aa2004c581db1c297e94b0eb90dd74122

On Wed, Jun 24, 2015 at 2:30 PM, Philip Durbin <philipdurbin_at_gmail.com> wrote:
> Hello Glassfish users!
>
> Does anyone know why the test case below works fine when I use
> mod_proxy_http but fails when I use mod_proxy_ajp?
>
> I originally posted this as a Payara issue but I'm quite sure it
> applies to Glassfish as well since we're using Glassfish in
> production: https://github.com/payara/Payara/issues/350
>
> I have since uploaded the war file I'm testing with if it's of
> interest: https://github.com/IQSS/apachetest/releases/download/v0.1/apachetest-0.1.war
>
> I'd be happy to provide a Vagrantfile to demo the Apache side of
> things if that's of interest.
>
> Phil
>
> ## Summary
>
> I'm using Payara 4.1.152.1 behind Apache 2.2 (specifically, the
> version that ships with CentOS 6: `httpd-2.2.15-39.el6.centos.x86_64`)
> and I'm getting `java.lang.OutOfMemoryError: Java heap space` and "503
> Service Temporarily Unavailable" when I try to use AJP
> (`mod_proxy_ajp`) when downloading a gigabyte from a [simple
> app](https://github.com/IQSS/apachetest) that [allows an arbitrary
> number of bytes to be
> streamed](https://github.com/IQSS/apachetest/blob/master/src/main/java/org/dataverse/apachetest/api/Download.java).
> I don't see the problem when I don't use AJP.
>
> ## How to reproduce
>
> - `asadmin start-domain domain1`
> - enable listener port with `asadmin create-network-listener
> --protocol http-listener-1 --listenerport 8009 --jkenabled true
> jk-connector`
> - deploy apachetest-0.1.war built from https://github.com/IQSS/apachetest
> - download a one gigabyte file (1 billion bytes) with
> http://example.com/apachetest-0.1/api/download/streamBytes/1000000000
>
> Expected behavior: The file is downloaded without incident
>
> Actual behavior: Payara logs `java.lang.OutOfMemoryError: Java heap
> space` and the client reports "503 Service Temporarily Unavailable".
>
> ## Without AJP everything works
>
> Below is the output of `curl` when AJP is **not** used. Everything
> works fine. No 503 errors. The Apache config looks like this:
>
> ```
> <VirtualHost *:80>
> ServerName example.com
> ProxyPass / http://localhost:8080/
> ProxyPassReverse / http://localhost:8080/
> </VirtualHost>
> ```
>
> The most important output below is the line indicating `200 OK`. The
> one gigabyte file was downloaded without indicent:
>
> ```
> murphy:apachetest pdurbin$ curl -v
> http://pdurbin.iq.harvard.edu/apachetest-0.1/api/download/streamBytes/1000000000
>> /dev/null
> * Hostname was NOT found in DNS cache
> % Total % Received % Xferd Average Speed Time Time Time Current
> Dload Upload Total Spent Left Speed
> 0 0 0 0 0 0 0 0 --:--:-- --:--:--
> --:--:-- 0* Trying 140.247.115.167...
> * Connected to pdurbin.iq.harvard.edu (140.247.115.167) port 80 (#0)
>> GET /apachetest-0.1/api/download/streamBytes/1000000000 HTTP/1.1
>> User-Agent: curl/7.37.1
>> Host: pdurbin.iq.harvard.edu
>> Accept: */*
>>
> < HTTP/1.1 200 OK
> < Date: Mon, 22 Jun 2015 18:51:39 GMT
> * Server Payara Server Open Source Edition 4.1.152.1 #badassfish is
> not blacklisted
> < Server: Payara Server Open Source Edition 4.1.152.1 #badassfish
> < X-Powered-By: Servlet/3.1 JSP/2.3 (Payara Server Open Source Edition
> 4.1.152.1 #badassfish Java/Oracle Corporation/1.7)
> < Content-Type: application/octet-stream
> < Connection: close
> < Transfer-Encoding: chunked
> <
> { [data not shown]
> 100 953M 0 953M 0 0 8266k 0 --:--:-- 0:01:58 --:--:-- 8401k
> * Closing connection 0
> murphy:apachetest pdurbin$
> ```
> ## Using AJP results in OutOfMemoryError and 503 errors
>
> In order to use AJP we first enable 8009 as the listener port:
> `asadmin create-network-listener --protocol http-listener-1
> --listenerport 8009 --jkenabled true jk-connector`
>
> Then we modify the Apache config to use `mod_proxy_ajp` rather than
> `mod_proxy_http`:
>
> ```
> <VirtualHost *:80>
> ServerName example.com
> ProxyPass / ajp://localhost:8009/
> ProxyPassReverse / ajp://localhost:8009/
> </VirtualHost>
> ```
>
> Then we repeat the curl command that worked fine when we were not
> using AJP. Notice that we see "503 Service Temporarily Unavailable":
>
> ```
> murphy:apachetest pdurbin$ curl -v
> http://pdurbin.iq.harvard.edu/apachetest-0.1/api/download/streamBytes/1000000000
>> /dev/null
> * Hostname was NOT found in DNS cache
> % Total % Received % Xferd Average Speed Time Time Time Current
> Dload Upload Total Spent Left Speed
> 0 0 0 0 0 0 0 0 --:--:-- --:--:--
> --:--:-- 0* Trying 140.247.115.167...
> * Connected to pdurbin.iq.harvard.edu (140.247.115.167) port 80 (#0)
>> GET /apachetest-0.1/api/download/streamBytes/1000000000 HTTP/1.1
>> User-Agent: curl/7.37.1
>> Host: pdurbin.iq.harvard.edu
>> Accept: */*
>>
> 0 0 0 0 0 0 0 0 --:--:-- 0:01:00
> --:--:-- 0< HTTP/1.1 503 Service Temporarily Unavailable
> < Date: Mon, 22 Jun 2015 18:34:43 GMT
> < Content-Length: 411
> < Connection: close
> < Content-Type: text/html; charset=iso-8859-1
> <
> { [data not shown]
> 100 411 100 411 0 0 6 0 0:01:08 0:01:00 0:00:08 101
> * Closing connection 0
> murphy:apachetest pdurbin$
> ```
>
> Here is the `OutOfMemoryError` error we see in
> /home/payara/payara41/glassfish/domains/domain1/logs/server.log
>
> ```
> [2015-06-22T14:35:40.097-0400] [Payara 4.1] [SEVERE]
> [AS-WEB-CORE-00037] [javax.enterprise.web.core] [tid: _ThreadID=119
> _ThreadName=jk-connector(1)] [timeMillis: 1434998140097] [levelValue:
> 1000] [[
> An exception or error occurred in the container during the request processing
> java.lang.OutOfMemoryError: Java heap space
> at java.util.Arrays.copyOf(Arrays.java:2367)
> at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:130)
> at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:114)
> at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:415)
> at java.lang.StringBuilder.append(StringBuilder.java:132)
> at com.sun.enterprise.server.logging.UniformLogFormatter.uniformLogFormat(UniformLogFormatter.java:457)
> at com.sun.enterprise.server.logging.UniformLogFormatter.format(UniformLogFormatter.java:178)
> at java.util.logging.StreamHandler.publish(StreamHandler.java:196)
> at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:105)
> at java.util.logging.Logger.log(Logger.java:616)
> at java.util.logging.Logger.doLog(Logger.java:641)
> at java.util.logging.Logger.logp(Logger.java:757)
> at com.sun.enterprise.web.logger.IASLogger.write(IASLogger.java:127)
> at com.sun.enterprise.web.logger.LoggerBase.write(LoggerBase.java:230)
> at com.sun.enterprise.web.logger.LoggerBase.log(LoggerBase.java:204)
> at com.sun.enterprise.web.logger.IASLogger.log(IASLogger.java:57)
> at org.apache.catalina.core.StandardWrapperValve.log(StandardWrapperValve.java:465)
> at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:357)
> at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:160)
> at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:734)
> at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:673)
> at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:99)
> at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:174)
> at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:415)
> at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:282)
> at com.sun.enterprise.v3.services.impl.ContainerMapper$HttpHandlerCallable.call(ContainerMapper.java:459)
> at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:167)
> at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:206)
> at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:180)
> at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:235)
> at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
> at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:283)
> ]]
>
> [2015-06-22T14:35:52.037-0400] [Payara 4.1] [WARNING] []
> [org.glassfish.grizzly.filterchain.DefaultFilterChain] [tid:
> _ThreadID=119 _ThreadName=jk-connector(1)] [timeMillis: 1434998152037]
> [levelValue: 900] [[
> GRIZZLY0013: Exception during FilterChain execution
> java.lang.OutOfMemoryError: Java heap space
> at java.util.Arrays.copyOf(Arrays.java:2219)
> at org.glassfish.grizzly.memory.BuffersBuffer.ensureBuffersCapacity(BuffersBuffer.java:316)
> at org.glassfish.grizzly.memory.BuffersBuffer.append(BuffersBuffer.java:240)
> at org.glassfish.grizzly.memory.BuffersBuffer.split(BuffersBuffer.java:478)
> at org.glassfish.grizzly.http.ajp.AjpMessageUtils.appendContentAndTrim(AjpMessageUtils.java:486)
> at org.glassfish.grizzly.http.ajp.AjpHandlerFilter.encodeHttpPacket(AjpHandlerFilter.java:275)
> at org.glassfish.grizzly.http.ajp.AjpHandlerFilter.handleWrite(AjpHandlerFilter.java:244)
> at org.glassfish.grizzly.filterchain.ExecutorResolver$8.execute(ExecutorResolver.java:111)
> at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:283)
> at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:200)
> at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:132)
> at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:111)
> at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
> at org.glassfish.grizzly.filterchain.FilterChainContext.write(FilterChainContext.java:890)
> at org.glassfish.grizzly.filterchain.FilterChainContext.write(FilterChainContext.java:858)
> at org.glassfish.grizzly.http.io.OutputBuffer.flushBuffer(OutputBuffer.java:1029)
> at org.glassfish.grizzly.http.io.OutputBuffer.flushBinaryBuffers(OutputBuffer.java:1016)
> at org.glassfish.grizzly.http.io.OutputBuffer.flushAllBuffers(OutputBuffer.java:987)
> at org.glassfish.grizzly.http.io.OutputBuffer.close(OutputBuffer.java:716)
> at org.glassfish.grizzly.http.io.OutputBuffer.endRequest(OutputBuffer.java:379)
> at org.glassfish.grizzly.http.server.Response.finish(Response.java:516)
> at org.glassfish.grizzly.http.server.HttpServerFilter.afterService(HttpServerFilter.java:384)
> at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:260)
> at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
> at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:283)
> at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:200)
> at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:132)
> at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:111)
> at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
> at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:536)
> at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
> at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:117)
> ]]
> ```