Bug 33810 - Stream closed errors from JSP tags under load
Summary: Stream closed errors from JSP tags under load
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 5
Classification: Unclassified
Component: Jasper (show other bugs)
Version: 5.0.28
Hardware: PC Linux
: P1 critical (vote)
Target Milestone: ---
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2005-03-02 17:43 UTC by Purush Rudrakshala
Modified: 2005-03-26 00:28 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Purush Rudrakshala 2005-03-02 17:43:12 UTC
We have a Struts based application deployed on JBoss 3.2.6. In our production
environment under load the servers throw "Stream closed" errors and after that
the servers do not work and forced to restart.  We have not seen this problem in
test regions where the load is lower.  We have tried disabling tag pooling in
Tomcat, but that does not seem to help fix the problems. Does any one else have
similar issues in production environment?

The server encountered an internal error () that prevented it from fulfilling
this request.
exception
java.io.IOException: Stream closed
org.apache.jasper.runtime.BodyContentImpl.ensureOpen(BodyContentImpl.java:576)
org.apache.jasper.runtime.BodyContentImpl.write(BodyContentImpl.java:140)
org.apache.jasper.runtime.BodyContentImpl.write(BodyContentImpl.java:157)
org.apache.jsp.protected_.security.AvailApplications_jsp._jspService(AvailApplications_jsp.java:210)
org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:94)
javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:324)
org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:292)
org.apache.jasper.servlet.JspServlet.service(JspServlet.java:236)
javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
org.apache.struts.action.RequestProcessor.doForward(RequestProcessor.java:1069)
org.apache.struts.action.RequestProcessor.processForwardConfig(RequestProcessor.java:455)
com.citistreet.id.i401k.struts.util.PwebRequestProcessor.processForwardConfig(PwebRequestProcessor.java:96)
org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:279)
org.apache.struts.action.ActionServlet.process(ActionServlet.java:1482)
citistreet.id.struts.action.AbstractController.process(AbstractController.java:141)
com.citistreet.id.i401k.struts.action.Controller.process(Controller.java:142)
org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:507)
javax.servlet.http.HttpServlet.service(HttpServlet.java:697)
citistreet.id.struts.action.AbstractController.service(AbstractController.java:108)
com.citistreet.id.i401k.struts.action.Controller.service(Controller.java:118)
javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
citistreet.id.servlet.filter.AbstractFilter.doFilter(AbstractFilter.java:79)
citistreet.id.servlet.filter.AbstractFilter.doFilter(AbstractFilter.java:79)
com.citistreet.id.i401k.servlet.filter.TimingFilter.doFilter(TimingFilter.java:54)
org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:75)

Thanks
Purush
Comment 1 Tim Funk 2005-03-03 00:08:42 UTC
Sounds like the client closed the connection while still writing content. Please
use tomcat-user to debug this
Comment 2 Purush Rudrakshala 2005-03-03 01:50:23 UTC
All this is happening from JSPs that use JSP tags. These JSPs work fine under
normal load. If the stream is closed incorrectly by user code then this should
happen all the time, not just under load.
Comment 3 Tim Funk 2005-03-03 03:01:48 UTC
Looking at BodyContentImpl - the error is thrown if something tries to call
write some time after close was already called on the BodyContent. Why close was
called is up to your code. (For example, sendredirects, writing to stream after
a forwards, ...)
Comment 4 Purush Rudrakshala 2005-03-03 04:14:17 UTC
There are no explicit stream closes in JSP. The JSPs use Struts tags which work
fine for some time and fail with these errors after some time and under load. If
it  is a code issue it should fail consistently under normal cases too. This
could be a  problem with how Tomcat handles JSP tags at run-time. If you need
more information, I will be glad to provide.
Comment 5 Tim Funk 2005-03-03 12:21:31 UTC
Your code has a concurrency issue. Use tomcat-user to debug.
Comment 6 Purush Rudrakshala 2005-03-03 14:43:27 UTC
There is no user code. It is JSP tags + code generated by Tomcat for the JSP.
Are you suggesting there is a concurrency issue in Tomcat runtime and/or
generated code for JSP pages with tags?
Comment 7 Tim Funk 2005-03-03 14:52:10 UTC
use tomcat-user
Comment 8 Purush Rudrakshala 2005-03-03 14:58:41 UTC
(In reply to comment #7)
> use tomcat-user

Thanks. I have already posted to tomcat-user mailing list.
Comment 9 Purush Rudrakshala 2005-03-07 14:13:53 UTC
I have been looking at Jasper source for this problem as I did not much help
from tomcat-user mailing list. 

I think there are some problems related to PageContextImpl pooling. Please take
a moment to look at the details.

org.apache.jasper.runtime.JspFactoryImpl class by default pools PageContextImpl
objects. PageContextImpl.initialize() is called when a pc is retrieved from the
pool, and PageContextImpl.release() is called when a pc is returned to the pool.

Looking at the org.apache.jasper.runtime.PageContextImpl class, the data member
"outs" which is BodyContentImpl[] is not cleared both in initialize and release
methods. 

Looking at the stack trace attached with this bug report, I think this may be
the cause of problems with our application. I am going to try disabling
PageContextImpl pooling and see.
Comment 10 Tim Funk 2005-03-07 14:31:52 UTC
Remy has committed a fix. See ..
http://marc.theaimsgroup.com/?l=tomcat-dev&m=110995942120860&w=2

This may fix this issue.
Comment 11 Purush Rudrakshala 2005-03-07 14:44:38 UTC
Remy's fix may not fix the problem. The "closed" flag is set in setWriter()
method, but the "Stream closed" exceptions happen in ensureOpen() which is
called when writer == null.
Comment 12 Remy Maucherat 2005-03-07 15:00:30 UTC
This has been fixed. Please do not reopen the report.
Comment 13 Remy Maucherat 2005-03-08 02:04:09 UTC
Please look in the code which uses BodyContentImpl. setWriter will always be
called by PageContextImpl.pushBody.
Comment 14 Purush Rudrakshala 2005-03-08 06:44:43 UTC
I have looked at the code. Please take a look at the stack trace and the
BodyContentImpl code. As the stack trace shows the exception is from
ensureOpen() call. if setWriter() is called always this should not happen
according to the code
Comment 15 Purush Rudrakshala 2005-03-08 11:15:24 UTC
Okay. Setting the "closed" flag in setWriter() called from
PageContextImpl.pushBody() should avoid "Stream closed" exception from
ensureOpen(). 

I still think some thing may be wrong in recycling PageContextImpl objects. Can
you please look at comment# 9?
Comment 16 Remy Maucherat 2005-03-08 11:41:37 UTC
No, recycling of the BodyContent objects is not needed (well, it is needed, and
done in setWriter, which is always called by pushBody). If you disagree, please
provide tangible proof.

If you want to disable this anyway, it's easy to do.
Comment 17 Purush Rudrakshala 2005-03-08 12:40:58 UTC
Thanks for your help and clarifications. I will give this a try and see how it
works.
Comment 18 Purush Rudrakshala 2005-03-09 08:47:29 UTC
Another related question. If "closed" flag was not initialized properly in
BodyContentImpl.setWriter(), one would expect to fail with "Stream closed"
exceptions consistently for a specific application such as ours, but this is not
the case. The application runs fine for a few hours without any issues and all
of a sudden these errors occur. Any reason or theory for this behavior?
Comment 19 Purush Rudrakshala 2005-03-24 08:56:50 UTC
Update: We have been using with the patched version of jasper-runtime.jar for a
few weeks. In our test regions, we start getting the following errors after
running successfully for few hours, and at this time, only option is to restart
the server.

Here is the detailed stack trace:

2005-03-23 02:21:14,731 ERROR [org.jboss.web.localhost.Engine]
ApplicationDispatcher[] Servlet.service() for servlet jsp threw exception
java.lang.NullPointerException
	at org.apache.jasper.runtime.BodyContentImpl.reAllocBuff(BodyContentImpl.java:585)
	at org.apache.jasper.runtime.BodyContentImpl.write(BodyContentImpl.java:142)
	at org.apache.jasper.runtime.BodyContentImpl.write(BodyContentImpl.java:157)
	at
org.apache.jsp.protected_.inquiry.participant.ParticipantSummary_jsp._jspx_meth_res_encodeUrl_0(Unknown
Source)
	at
org.apache.jsp.protected_.inquiry.participant.ParticipantSummary_jsp._jspx_meth_req_equalsParameter_0(Unknown
Source)
	at
org.apache.jsp.protected_.inquiry.participant.ParticipantSummary_jsp._jspService(Unknown
Source)
	at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:94)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
	at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:324)
	at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:292)
	at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:236)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
	at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
	at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
	at
org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:704)
	at
org.apache.catalina.core.ApplicationDispatcher.doInclude(ApplicationDispatcher.java:590)
	at
org.apache.catalina.core.ApplicationDispatcher.include(ApplicationDispatcher.java:510)
	at org.apache.jasper.runtime.JspRuntimeLibrary.include(JspRuntimeLibrary.java:966)
	at org.apache.jasper.runtime.PageContextImpl.include(PageContextImpl.java:602)
	at com.citistreet.id.i401k.util.JspUtility.include(JspUtility.java:66)
	at org.apache.jsp.protected_.common.ipsrPage_jsp._jspService(Unknown Source)
	at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:94)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
	at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:324)
	at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:292)
	at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:236)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
	at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
	at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
	at
org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:704)
	at
org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:474)
	at
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:409)
	at
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:312)
	at org.apache.struts.action.RequestProcessor.doForward(RequestProcessor.java:1069)
	at
org.apache.struts.action.RequestProcessor.processForwardConfig(RequestProcessor.java:455)
	at
com.citistreet.id.i401k.struts.util.PwebRequestProcessor.processForwardConfig(PwebRequestProcessor.java:96)
	at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:279)
	at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1482)
	at
citistreet.id.struts.action.AbstractController.process(AbstractController.java:141)
	at com.citistreet.id.i401k.struts.action.Controller.process(Controller.java:142)
	at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:507)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:697)
	at
citistreet.id.struts.action.AbstractController.service(AbstractController.java:108)
	at com.citistreet.id.i401k.struts.action.Controller.service(Controller.java:118)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
	at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
	at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
	at
org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:704)
	at
org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:474)
	at
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:409)
	at
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:312)
	at org.apache.struts.action.RequestProcessor.doForward(RequestProcessor.java:1069)
	at
org.apache.struts.action.RequestProcessor.processForwardConfig(RequestProcessor.java:455)
	at
com.citistreet.id.i401k.struts.util.PwebRequestProcessor.processForwardConfig(PwebRequestProcessor.java:96)
	at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:279)
	at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1482)
	at
citistreet.id.struts.action.AbstractController.process(AbstractController.java:141)
	at com.citistreet.id.i401k.struts.action.Controller.process(Controller.java:142)
	at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:507)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:697)
	at
citistreet.id.struts.action.AbstractController.service(AbstractController.java:108)
	at com.citistreet.id.i401k.struts.action.Controller.service(Controller.java:118)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
	at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
	at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
	at citistreet.id.servlet.filter.AbstractFilter.doFilter(AbstractFilter.java:79)
	at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:186)
	at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
	at citistreet.id.servlet.filter.AbstractFilter.doFilter(AbstractFilter.java:79)
	at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:186)
	at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
	at
com.citistreet.id.i401k.servlet.filter.TimingFilter.doFilter(TimingFilter.java:54)
	at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:186)
	at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
	at
org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:75)
	at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:186)
	at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
	at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:214)
	at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
	at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
	at
org.apache.catalina.core.StandardContextValve.invokeInternal(StandardContextValve.java:198)
	at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:152)
	at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
	at
org.jboss.web.tomcat.security.CustomPrincipalValve.invoke(CustomPrincipalValve.java:66)
	at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
	at
org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:158)
	at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
	at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:462)
	at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
	at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:137)
	at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:118)
	at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
	at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:535)
	at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
	at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
	at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
	at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
	at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:929)
	at org.apache.coyote.tomcat5.CoyoteAdapter.service(CoyoteAdapter.java:160)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:799)
	at
org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:705)
	at org.apache.tomcat.util.net.TcpWorkerThread.runIt(PoolTcpEndpoint.java:577)
	at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:683)
	at java.lang.Thread.run(Thread.java:534)
Comment 20 Remy Maucherat 2005-03-24 15:59:00 UTC
As I said, if you wanted to avoid this kind of problems (which I do not mind
fixing), you should avoid using close inside your tags, which is completely useless.
Comment 21 Purush Rudrakshala 2005-03-24 18:34:39 UTC
(In reply to comment #20)
> As I said, if you wanted to avoid this kind of problems (which I do not mind
> fixing), you should avoid using close inside your tags, which is completely
useless.

I am not asking you to fix my tags. These are standard jakarta tags from taglibs
project. Please take a look at the stack trace. These are from BodyContentImpl
class from jasper runtime. There are no close() calls from the tags. This is an
issue that is internal to Tomcat/Jasper most probably from pooling of jasper
runtime objects. The same application was working fine for years with Weblogic
servers. Can you explain why it would work for few hours and fail later? If it
is due to close() calls from tag implementation, it should fail all the time. 
Comment 22 Purush Rudrakshala 2005-03-25 02:05:26 UTC
I am re-opening this bug. Please provide explanation before closing. This
problem is in our production systems and we are forced to restart instances
several times.
Comment 23 Remy Maucherat 2005-03-25 11:01:50 UTC
That was just an advice that you shouldn't be calling close in your tags since
it is useless (obviously, the tag calling close will not be the one then
experiencing the exception: it can be fairly random).
I marked the bug as fixed since I fixed the issue in CVS.
Comment 24 Purush Rudrakshala 2005-03-25 14:35:37 UTC
Are you talking about the fix you made in BodyContentImpl.setWriter() method to
set closed = false? If so, please note that this is happening "after" the fix.
We are using the patched jasper-runtime.jar with that fix.

Or, Did you make a new fix after I re-opened the bug?
Comment 25 Remy Maucherat 2005-03-25 17:19:15 UTC
Yes, I did make a new change in CVS.
Comment 26 Purush Rudrakshala 2005-03-26 03:20:19 UTC
I checked tomcat-dev mailing list for cvs-commit messages by you. I did not see
it in there. Can you please tell me what classes changed exactly?
Comment 27 Remy Maucherat 2005-03-26 09:28:42 UTC
remm        2005/03/24 03:41:29

  Modified:    jasper2/src/share/org/apache/jasper/runtime
                        BodyContentImpl.java
  Log:
  - Close shouldn't null the char buffer.
  
  Revision  Changes    Path
  1.15      +0 -1     
jakarta-tomcat-jasper/jasper2/src/share/org/apache/jasper/runtime/BodyContentImpl.java
  
  Index: BodyContentImpl.java
  ===================================================================
  RCS file:
/home/cvs/jakarta-tomcat-jasper/jasper2/src/share/org/apache/jasper/runtime/BodyContentImpl.java,v
  retrieving revision 1.14
  retrieving revision 1.15
  diff -u -r1.14 -r1.15
  --- BodyContentImpl.java	4 Mar 2005 18:00:41 -0000	1.14
  +++ BodyContentImpl.java	24 Mar 2005 11:41:29 -0000	1.15
  @@ -496,7 +496,6 @@
   	if (writer != null) {
   	    writer.close();
   	} else {
  -	    cb = null;	
   	    closed = true;
   	}
       }