users@glassfish.java.net

[gf-users] 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, 24 Jun 2015 14:30:48 -0400

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)
]]
```