[GLASSFISH-20665] Grizzly generates a http 500 with simple index.html request under load / (maybe Grizzly closes the clients half-closed Sockets) Created: 26/Jun/13  Updated: 19/Sep/14  Resolved: 03/Jul/13

Status: Resolved
Project: glassfish
Component/s: grizzly-kernel
Affects Version/s: None
Fix Version/s: 4.1

Type: Bug Priority: Major
Reporter: iceandfire Assignee: oleksiys
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Debian Linux


Tags: grizzly

 Description   

I'm seeing 500 in my production monitoring.
The test there is just requesting

"GET / HTTP/1.0 \nUser-Agent:LogicMonitor\nConnection: close\n\n"

After this implemented a small bash test:

#!/bin/bash
while [ 1 ]; do
d=$(date +'%Y-%m-%d-%H:%M:%S-%N')
echo $d
curl -o testin.txt --connect-timeout 65 --max-time 60 "myhost?$d"
if grep -q copyright "testin.txt"; then
date
echo "Found"
rm testin.txt
else
date
echo "Not Found"
exit
fi
sleep 1
done
This exits every couple of minutes with "Not Found".

With higher load this happens faster.

On my testing platform I don't see this issue.

Same application on Jetty(comparable load)
-with a thread pool of 2000, but it's peeking only on 100 concurrent threads, so load should no be the issue -
doesn't show those http 500s.

I think both tests are http 1.0.

With a patch (https://www.java.net/forum/topic/glassfish/glassfish/glassfish-v4-sends-sometimes-empty-response-curl-o-testintxt-myservercom-under-load-accesslog-sh) for grizzly logging I got:

2013-06-26T09:52:07.724+0200] [glassfish 4.0] [WARNING] [] [javax.enterprise.web] [tid: _ThreadID=107 _ThreadName=http-listener-1(88)] [timeMillis: 1372233127724] [levelValue: 900] [[
  StandardWrapperValve[show]: Servlet.service() for servlet show threw exception
java.io.IOException: Connection closed
        at org.glassfish.grizzly.asyncqueue.TaskQueue.onClose(TaskQueue.java:302)
        at org.glassfish.grizzly.nio.AbstractNIOAsyncQueueWriter.onClose(AbstractNIOAsyncQueueWriter.java:591)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.closeConnection(TCPNIOTransport.java:611)
        at org.glassfish.grizzly.nio.NIOConnection$2.run(NIOConnection.java:438)
        at org.glassfish.grizzly.nio.DefaultSelectorHandler$RunnableTask.run(DefaultSelectorHandler.java:487)
        at org.glassfish.grizzly.nio.DefaultSelectorHandler.processPendingTaskQueue(DefaultSelectorHandler.java:293)
        at org.glassfish.grizzly.nio.DefaultSelectorHandler.processPendingTasks(DefaultSelectorHandler.java:284)
        at org.glassfish.grizzly.nio.DefaultSelectorHandler.preSelect(DefaultSelectorHandler.java:100)
        at org.glassfish.grizzly.nio.SelectorRunner.doSelect(SelectorRunner.java:329)
        at org.glassfish.grizzly.nio.SelectorRunner.run(SelectorRunner.java:274)
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:564)
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:544)
        at java.lang.Thread.run(Thread.java:722)
Caused by: java.lang.Exception: Close stack trace
        at org.glassfish.grizzly.nio.NIOConnection.close0(NIOConnection.java:425)
        at org.glassfish.grizzly.nio.transport.TCPNIOConnection.close0(TCPNIOConnection.java:291)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.read(TCPNIOTransport.java:938)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOTransportFilter.java:75)
        at org.glassfish.grizzly.filterchain.TransportFilter.handleRead(TransportFilter.java:173)
        at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:288)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:206)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:136)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:114)
        at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:838)
        at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:113)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:115)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:55)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:135)
        ... 3 more
]]

In the forum oleksiys said:

I think the client closes a Socket output (makes the Socket half-closed) and the server, in response, closes the Socket completely, when there is still some data to be written.



 Comments   
Comment by oleksiys [ 26/Jun/13 ]

can you pls. try this patch
https://dl.dropboxusercontent.com/u/7319744/nucleus-grizzly-all.jar

you'll get larger exception this time

thank you in advance.

Comment by iceandfire [ 27/Jun/13 ]

Hi I have installed the new patch:

[2013-06-27T08:48:41.578+0200] [glassfish 4.0] [WARNING] [] [javax.enterprise.web] [tid: _ThreadID=185 _ThreadName=http-listener-1(166)] [timeMillis: 1372315721578] [levelValue: 900] [[
  StandardWrapperValve[default]: Servlet.service() for servlet default threw exception
java.io.IOException: I/O error occurred
        at org.glassfish.grizzly.http.io.OutputBuffer.handleAsyncErrors(OutputBuffer.java:917)
        at org.glassfish.grizzly.http.io.OutputBuffer.write(OutputBuffer.java:648)
        at org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:355)
        at org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:342)
        at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:161)
        at org.apache.catalina.servlets.DefaultServlet.copy(DefaultServlet.java:2069)
        at org.apache.catalina.servlets.DefaultServlet.serveResource(DefaultServlet.java:1092)
        at org.apache.catalina.servlets.DefaultServlet.doGet(DefaultServlet.java:518)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1682)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:318)
        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.core.StandardPipeline.doInvoke(StandardPipeline.java:734)
        at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:673)
        at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:354)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:260)
        at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:188)
        at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:191)
        at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:168)
        at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:189)
        at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:288)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:206)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:136)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:114)
        at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:838)
        at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:113)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:115)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:55)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:135)
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:564)
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:544)
        at java.lang.Thread.run(Thread.java:722)
Caused by: java.io.IOException: Connection closed
        at org.glassfish.grizzly.asyncqueue.TaskQueue.onClose(TaskQueue.java:302)
        at org.glassfish.grizzly.nio.AbstractNIOAsyncQueueWriter.onClose(AbstractNIOAsyncQueueWriter.java:591)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.closeConnection(TCPNIOTransport.java:611)
        at org.glassfish.grizzly.nio.NIOConnection$2.run(NIOConnection.java:438)
        at org.glassfish.grizzly.nio.DefaultSelectorHandler$RunnableTask.run(DefaultSelectorHandler.java:487)
        at org.glassfish.grizzly.nio.DefaultSelectorHandler.processPendingTaskQueue(DefaultSelectorHandler.java:293)
        at org.glassfish.grizzly.nio.DefaultSelectorHandler.processPendingTasks(DefaultSelectorHandler.java:284)
        at org.glassfish.grizzly.nio.DefaultSelectorHandler.preSelect(DefaultSelectorHandler.java:100)
        at org.glassfish.grizzly.nio.SelectorRunner.doSelect(SelectorRunner.java:329)
        at org.glassfish.grizzly.nio.SelectorRunner.run(SelectorRunner.java:274)
        ... 3 more
Caused by: java.lang.Exception: Close stack trace
        at org.glassfish.grizzly.nio.NIOConnection.close0(NIOConnection.java:425)
        at org.glassfish.grizzly.nio.transport.TCPNIOConnection.close0(TCPNIOConnection.java:291)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.read(TCPNIOTransport.java:938)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOTransportFilter.java:75)
        at org.glassfish.grizzly.filterchain.TransportFilter.handleRead(TransportFilter.java:173)
        at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:288)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:206)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:136)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:114)
        at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:838)
        at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:113)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:115)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:55)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:135)
        ... 3 more
]]
Comment by oleksiys [ 27/Jun/13 ]

Thank you for the stacktrace.
I've updated the patch (at the same location), will appreciate if you can try it.

I have couple of questions also

1) Are you using asynchronous Servlet 3.0/3.1 features, like startAsync() or may be non-blocking API introduced in Servlet 3.1?
2) Are you able to reproduce the same problem with zero load, when only the script is running, nothing else?
3) If 2) is negative, are you able to reproduce the problem when you load the server by requesting very simple Servlet (not the one you use in production)?

Thank you in advance.

Comment by iceandfire [ 28/Jun/13 ]

New Patch:

[2013-06-28T14:34:53.057+0200] [glassfish 4.0] [WARNING] [] [javax.enterprise.web] [tid: _ThreadID=160 _ThreadName=http-listener-1(141)] [timeMillis: 1372422893057] [levelValue: 900] [[
  StandardWrapperValve[default]: Servlet.service() for servlet default threw exception
java.io.IOException: I/O error occurred
        at org.glassfish.grizzly.http.io.OutputBuffer.handleAsyncErrors(OutputBuffer.java:917)
        at org.glassfish.grizzly.http.io.OutputBuffer.write(OutputBuffer.java:648)
        at org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:355)
        at org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:342)
        at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:161)
        at org.apache.catalina.servlets.DefaultServlet.copy(DefaultServlet.java:2069)
        at org.apache.catalina.servlets.DefaultServlet.serveResource(DefaultServlet.java:1092)
        at org.apache.catalina.servlets.DefaultServlet.doGet(DefaultServlet.java:518)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1682)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:318)
        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.core.StandardPipeline.doInvoke(StandardPipeline.java:734)
        at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:673)
        at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:354)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:260)
        at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:188)
        at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:191)
        at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:168)
        at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:189)
        at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:288)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:206)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:136)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:114)
        at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:838)
        at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:113)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:115)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:55)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:135)
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:564)
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:544)
        at java.lang.Thread.run(Thread.java:722)
Caused by: java.io.IOException: Connection closed [Thread[http-listener-1-kernel(5) SelectorRunner,5,main]]
        at org.glassfish.grizzly.asyncqueue.TaskQueue.onClose(TaskQueue.java:302)
        at org.glassfish.grizzly.nio.AbstractNIOAsyncQueueWriter.onClose(AbstractNIOAsyncQueueWriter.java:591)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.closeConnection(TCPNIOTransport.java:611)
        at org.glassfish.grizzly.nio.NIOConnection$2.run(NIOConnection.java:441)
        at org.glassfish.grizzly.nio.DefaultSelectorHandler$RunnableTask.run(DefaultSelectorHandler.java:487)
        at org.glassfish.grizzly.nio.DefaultSelectorHandler.processPendingTaskQueue(DefaultSelectorHandler.java:293)
        at org.glassfish.grizzly.nio.DefaultSelectorHandler.processPendingTasks(DefaultSelectorHandler.java:284)
        at org.glassfish.grizzly.nio.DefaultSelectorHandler.preSelect(DefaultSelectorHandler.java:100)
        at org.glassfish.grizzly.nio.SelectorRunner.doSelect(SelectorRunner.java:329)
        at org.glassfish.grizzly.nio.SelectorRunner.run(SelectorRunner.java:274)
        ... 3 more
Caused by: java.lang.Exception: Close stack trace [Thread[http-listener-1(160),5,main]]
        at org.glassfish.grizzly.nio.NIOConnection.close0(NIOConnection.java:426)
        at org.glassfish.grizzly.nio.transport.TCPNIOConnection.close0(TCPNIOConnection.java:291)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.read(TCPNIOTransport.java:938)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOTransportFilter.java:75)
        at org.glassfish.grizzly.filterchain.TransportFilter.handleRead(TransportFilter.java:173)
        at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:288)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:206)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:136)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:114)
        at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:838)
        at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:113)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:115)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:55)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:135)
        ... 3 more
Caused by: java.lang.Exception: Last OP_READ enabled stack trace [Thread[http-listener-1(141),5,main]]
        at org.glassfish.grizzly.nio.NIOConnection.enableIOEvent(NIOConnection.java:721)
        at org.glassfish.grizzly.strategies.AbstractIOStrategy$EnableInterestProcessingHandler.onComplete(AbstractIOStrategy.java:141)
        at org.glassfish.grizzly.ProcessorExecutor.complete(ProcessorExecutor.java:117)
        at org.glassfish.grizzly.ProcessorExecutor.complete0(ProcessorExecutor.java:219)
        at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:86)
        ... 8 more
Comment by iceandfire [ 28/Jun/13 ]

1) Are you using asynchronous Servlet 3.0/3.1 features, like startAsync() or may be non-blocking API introduced in Servlet 3.1?
No, what I'm using is:

ReentrantLock lock = null;
synchronized (this.getClass())
{
	lock = (ReentrantLock) lockCache.getElement(userId);
	if (lock == null)
        lock = new ReentrantLock();
	lockCache.addElement(fullId, lock);
}

lock.lock();
try
{
...

2) Are you able to reproduce the same problem with zero load, when only the script is running, nothing else?
=> NO
3) If 2) is negative, are you able to reproduce the problem when you load the server by requesting very simple Servlet (not the one you use in production)?
=> Going to try out

Comment by oleksiys [ 28/Jun/13 ]

If it would be easier for you - you can share the complete servlet code, or send it to me directly to (oleksiys [at] java.net).
What you're doing w/ locks is totally ok, don't see any problem there, but may be there is something else.

thank you in advance.

Comment by oleksiys [ 28/Jun/13 ]

Pls. disregard my previous comment.
I think I found the problem, can you pls. try new patch (at the same location)?

Thank you in advance.

Comment by iceandfire [ 02/Jul/13 ]

I think the last patch solved the issue.
My basic test doesn't show errors anymore.

What was changed?

Comment by oleksiys [ 03/Jul/13 ]

It was a problem in Grizzly.
When HTTP client doesn't read off an entire response and closes the connection - the error, which appears on server side may be propagated to a wrong request/response.

It will be fixed in Grizzly 2.3.4

Comment by oleksiys [ 28/Mar/14 ]

for the records, this issue corresponds to GRIZZLY-1536

Generated at Tue Sep 01 10:38:21 UTC 2015 using JIRA 6.2.3#6260-sha1:63ef1d6dac3f4f4d7db4c1effd405ba38ccdc558.