You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by bu...@apache.org on 2007/03/06 18:27:59 UTC

DO NOT REPLY [Bug 41772] New: - Brand new HttpServletResponse is already committed.

DO NOT REPLY TO THIS EMAIL, BUT PLEASE POST YOUR BUG�
RELATED COMMENTS THROUGH THE WEB INTERFACE AVAILABLE AT
<http://issues.apache.org/bugzilla/show_bug.cgi?id=41772>.
ANY REPLY MADE TO THIS MESSAGE WILL NOT BE COLLECTED AND�
INSERTED IN THE BUG DATABASE.

http://issues.apache.org/bugzilla/show_bug.cgi?id=41772

           Summary: Brand new HttpServletResponse is already committed.
           Product: Tomcat 5
           Version: 5.0.30
          Platform: Other
        OS/Version: other
            Status: NEW
          Severity: normal
          Priority: P2
         Component: Unknown
        AssignedTo: tomcat-dev@jakarta.apache.org
        ReportedBy: nathan.nelson@digitalbarista.com


I'm running on Suse 9.3 (I think) with tomcat 5.0.30 running under Java
1.5.0_07-b03.  I'm front-ending with Apache 2.2.0 using mod_jk set up to hit an
AJP 1.3 connector.  As far as I can tell, everything is configured correctly.

About 20% of the time, when I hit my application without handing in a session
ID, I get an "IllegalStateException: Cannot create a session after the response
has been committed".  The problem is at its worst when I hit my application
using a client OTHER than a web browser.  I have tried putting a ServletFilter
in front of my application to verify that 1) the session truly cannot be
created, and 2) that the response is actually committed before my code touches
it.  It appears my application is being handed an already commited
HttpServletResponse.

I have 3 separate applications running in the same tomcat instance.

1) a webservice powered first by Axis, and now by XFire.  This bug showed up
using both of these libraries.
2) a straight up servlet / JSP webapp powered by struts.
3) a struts-powered app used exclusively for dynamic image generation.

In the case of app 1, I ended up hacking XFire to not call
response.setBufferSize(), which kept it from triggering an
"IllegalStateException: response has already been committed."  I don't have any
remaining stack traces, as I did this fix several months ago and dumped them,
thinking this was the end of the issue.

In app #2 everything seems to work fine except occasionally on my login page,
where I get this problem occasionally when I hand in no SESSIONID or an expired
one.  A page refresh usually takes care of it.

In app #3, I'm generating images to be included in a dynamically generated PDF.
 I make a bunch of calls to this app in rapid succession (12-15 images per PDF)
and invariably, anywhere between 1 and 5 of them returns a content length of 0.
 I checked the logs and found this stack trace:

(NOTE: that stray line in my SessionFilter class is:
((HttpServletRequest)request).getSession(true);  If you need the whole content
of that filter, I can send it to you, but that's all it does at the moment.)

java.lang.IllegalStateException: Cannot create a session after the response has
been committed
        at
org.apache.coyote.tomcat5.CoyoteRequest.doGetSession(CoyoteRequest.java:2270)
        at
org.apache.coyote.tomcat5.CoyoteRequest.getSession(CoyoteRequest.java:2116)
        at
org.apache.coyote.tomcat5.CoyoteRequestFacade.getSession(CoyoteRequestFacade.java:528)
        at com.mycompany.util.SessionFilter.doFilter(SessionFilter.java:37)
        at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
        at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        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.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.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.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:300)
        at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:374)
        at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:743)
        at
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:675)
        at org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:866)
        at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)

I would shrug it off as my own bad code, except this occurs before ANY of my
code executes, other than the one line in the ServletFilter.

I set up an automated test, just to demonstrate the differences in the two
requests.  It hits the app 50 times in a row (one request at a time) and between
8 and 15 of the requests fail, every time I run it.  Here are the headers
returned by both a successful and unsuccessful request.

Headers for Request 0 (unsuccessful)
	Date - Tue, 06 Mar 2007 09:38:26 GMT
	Server - Apache/2.2.0 (Linux/SUSE)
	Content-Length - 0
	Content-Type - image/png
	Content Length - 0

Headers for Request 3 (successful)
	Date - Tue, 06 Mar 2007 09:38:30 GMT
	Server - Apache/2.2.0 (Linux/SUSE)
	Set-Cookie - JSESSIONID=E4F3D53DD87F132B1668E04A14C2BDC4; Path=/myapp
	Content-Length - 330
	Content-Type - image/png
	Content Length - 330

I can provide more info if needed.

-- 
Configure bugmail: http://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


DO NOT REPLY [Bug 41772] - Brand new HttpServletResponse is already committed.

Posted by bu...@apache.org.
DO NOT REPLY TO THIS EMAIL, BUT PLEASE POST YOUR BUG�
RELATED COMMENTS THROUGH THE WEB INTERFACE AVAILABLE AT
<http://issues.apache.org/bugzilla/show_bug.cgi?id=41772>.
ANY REPLY MADE TO THIS MESSAGE WILL NOT BE COLLECTED AND�
INSERTED IN THE BUG DATABASE.

http://issues.apache.org/bugzilla/show_bug.cgi?id=41772





------- Additional Comments From nathan.nelson@digitalbarista.com  2007-03-06 09:32 -------
Created an attachment (id=19672)
 --> (http://issues.apache.org/bugzilla/attachment.cgi?id=19672&action=view)
My test case - used to reproduce my problem.

I've attached the test case I used to reproduce my bug.  I have changed the URL
to edit out the host, application, and struts action mapping.  However, all
other parts of the file are as-is.

-- 
Configure bugmail: http://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


DO NOT REPLY [Bug 41772] - HttpServletResponse is already committed.

Posted by bu...@apache.org.
DO NOT REPLY TO THIS EMAIL, BUT PLEASE POST YOUR BUG�
RELATED COMMENTS THROUGH THE WEB INTERFACE AVAILABLE AT
<http://issues.apache.org/bugzilla/show_bug.cgi?id=41772>.
ANY REPLY MADE TO THIS MESSAGE WILL NOT BE COLLECTED AND�
INSERTED IN THE BUG DATABASE.

http://issues.apache.org/bugzilla/show_bug.cgi?id=41772


remm@apache.org changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|                            |WONTFIX




------- Additional Comments From remm@apache.org  2007-03-06 13:51 -------
This has been reported many times, and will not be patched, since enabling the
security manager fixes it.

-- 
Configure bugmail: http://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


DO NOT REPLY [Bug 41772] - HttpServletResponse is already committed.

Posted by bu...@apache.org.
DO NOT REPLY TO THIS EMAIL, BUT PLEASE POST YOUR BUG�
RELATED COMMENTS THROUGH THE WEB INTERFACE AVAILABLE AT
<http://issues.apache.org/bugzilla/show_bug.cgi?id=41772>.
ANY REPLY MADE TO THIS MESSAGE WILL NOT BE COLLECTED AND�
INSERTED IN THE BUG DATABASE.

http://issues.apache.org/bugzilla/show_bug.cgi?id=41772


nathan.nelson@digitalbarista.com changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           Severity|normal                      |minor
            Summary|Brand new                   |HttpServletResponse is
                   |HttpServletResponse is      |already committed.
                   |already committed.          |




------- Additional Comments From nathan.nelson@digitalbarista.com  2007-03-06 12:43 -------
So, sheepishly I admit that this is an application error, but I believe there's
still a weakness to be patched up.  

It relates back to the Java2D stuff I'm using.  After the following two lines:

ImageOutputStream out=ImageIO.createImageOutputStream(response.getOutputStream());
ImageIO.write(image,"png",out);
response.getOutputStream().flush();

I never closed ImageOutputStream.  Obviously an application error.  However, in
the catalina logs, I found this stack trace:

2007-03-05 07:00:01,167 [Finalizer] ERROR org.apache.jk.server.JkCoyoteHandler -
Error in action code
java.net.SocketException: Socket closed
        at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:99)
        at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
        at org.apache.jk.common.ChannelSocket.send(ChannelSocket.java:506)
        at org.apache.jk.server.JkCoyoteHandler.appendHead(JkCoyoteHandler.java:401)
        at org.apache.jk.server.JkCoyoteHandler.action(JkCoyoteHandler.java:416)
        at org.apache.coyote.Response.action(Response.java:182)
        at org.apache.coyote.Response.sendHeaders(Response.java:374)
        at org.apache.coyote.tomcat5.OutputBuffer.doFlush(OutputBuffer.java:322)
        at org.apache.coyote.tomcat5.OutputBuffer.flush(OutputBuffer.java:298)
        at
org.apache.coyote.tomcat5.CoyoteOutputStream.flush(CoyoteOutputStream.java:85)
        at
javax.imageio.stream.FileCacheImageOutputStream.close(FileCacheImageOutputStream.java:194)
        at
javax.imageio.stream.ImageInputStreamImpl.finalize(ImageInputStreamImpl.java:850)
        at java.lang.ref.Finalizer.invokeFinalizeMethod(Native Method)
        at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:83)
        at java.lang.ref.Finalizer.access$100(Finalizer.java:14)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:160)


During GC, that ImageOutputStream is trying to flush the response output stream.
 It seems like Tomcat recycles HttpServletResponse objects.  If this finalizer
is executed AFTER the Response object it references is recycled, the resulting
'flush()' would cause that Response object to become committed.  When a new
request then comes in to be handled by a thread with a now broken Response
object . . . well, there's where my error comes from.

I also believe this bug report relates directly to bug #37516.  Note that in the
example code provided in that bug, he ALSO does not close his image output
stream.  My apologies for duplicating a previous bug.

While I understand this is my application's bug, it seems that recycling
Response objects should be a bit more safe than it currently is.

-- 
Configure bugmail: http://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org