Uploaded image for project: 'Confluence Data Center'
  1. Confluence Data Center
  2. CONFSERVER-9984

Superfluous exception logging from createrssfeed.action (java.io.IOException: WEB8001: Write failed)

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: Low Low
    • 2.7
    • 2.5.8
    • None
    • Sun Java System Web Server 7 Update 1 on Solaris 10 with JDK 1.5.0_u09

      Some RSS clients are misbehaving and request an RSS feed, but then close the connection before the RSS results can be written back.

      RssResult.java throws the IOException when it tries to flush the buffer and write to the client and the connection is closed.

      (com.atlassian.xwork.results.RssResult.java in atlassian-bucket)

      Attached is a patch that catches the exception and logs some information about what happened.

      Here's the stacktrace:

      ERROR 2007-09-14 04:18:07,986 [service-j2ee-39] ServletDispatcher:serviceAction - Could not execute action
      – url: /createrssfeed.action | userName: anonymous
      ClientAbortException: java.io.IOException: WEB8001: Write failed
      at org.apache.coyote.tomcat5.OutputBuffer.realWriteBytes(OutputBuffer.java:385)
      at org.apache.tomcat.util.buf.ByteChunk.flushBuffer(ByteChunk.java:404)
      at org.apache.coyote.tomcat5.OutputBuffer.doFlush(OutputBuffer.java:334)
      at org.apache.coyote.tomcat5.OutputBuffer.flush(OutputBuffer.java:313)
      at org.apache.coyote.tomcat5.CoyoteResponse.flushBuffer(CoyoteResponse.java:622)
      at com.sun.webserver.connector.nsapi.NSAPIResponse.flushBuffer(NSAPIResponse.java:125)
      at org.apache.coyote.tomcat5.CoyoteResponseFacade.flushBuffer(CoyoteResponseFacade.java:278)
      at javax.servlet.ServletResponseWrapper.flushBuffer(ServletResponseWrapper.java:176)
      at javax.servlet.ServletResponseWrapper.flushBuffer(ServletResponseWrapper.java:176)
      at com.atlassian.xwork.results.RssResult.doExecute(RssResult.java:42)
      at com.opensymphony.webwork.dispatcher.WebWorkResultSupport.execute(WebWorkResultSupport.java:116)
      at com.opensymphony.xwork.DefaultActionInvocation.executeResult(DefaultActionInvocation.java:263)
      at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:187)
      at com.opensymphony.xwork.interceptor.AroundInterceptor.intercept(AroundInterceptor.java:35)
      at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:165)
      at com.atlassian.confluence.util.LoggingContextInterceptor.intercept(LoggingContextInterceptor.java:48)
      at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:165)
      at com.atlassian.confluence.security.actions.PermissionCheckInterceptor.intercept(PermissionCheckInterceptor.java:47)
      at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:165)
      at com.atlassian.confluence.pages.actions.PageAwareInterceptor.intercept(PageAwareInterceptor.java:114)
      at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:165)
      at com.atlassian.confluence.spaces.actions.SpaceAwareInterceptor.intercept(SpaceAwareInterceptor.java:67)
      at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:165)
      at com.opensymphony.xwork.interceptor.AroundInterceptor.intercept(AroundInterceptor.java:35)
      at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:165)
      at com.atlassian.confluence.core.actions.LastModifiedInterceptor.intercept(LastModifiedInterceptor.java:39)
      at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:165)
      at com.atlassian.confluence.core.ConfluenceAutowireInterceptor.intercept(ConfluenceAutowireInterceptor.java:25)
      at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:165)
      at com.opensymphony.xwork.interceptor.AroundInterceptor.intercept(AroundInterceptor.java:35)
      at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:165)
      at com.opensymphony.xwork.interceptor.AroundInterceptor.intercept(AroundInterceptor.java:35)
      at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:165)
      at com.atlassian.xwork.interceptors.XWorkTransactionInterceptor.intercept(XWorkTransactionInterceptor.java:98)
      at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:165)
      at com.opensymphony.xwork.interceptor.AroundInterceptor.intercept(AroundInterceptor.java:35)
      at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:165)
      at com.opensymphony.xwork.DefaultActionProxy.execute(DefaultActionProxy.java:115)
      at com.opensymphony.webwork.dispatcher.ServletDispatcher.serviceAction(ServletDispatcher.java:229)
      at com.opensymphony.webwork.dispatcher.ServletDispatcher.service(ServletDispatcher.java:199)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:917)
      at org.apache.catalina.core.ApplicationFilterChain.servletService(ApplicationFilterChain.java:398)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:304)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at com.opensymphony.module.sitemesh.filter.PageFilter.parsePage(PageFilter.java:117)
      at com.atlassian.confluence.util.profiling.ProfilingPageFilter.parsePage(ProfilingPageFilter.java:137)
      at com.opensymphony.module.sitemesh.filter.PageFilter.doFilter(PageFilter.java:51)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:217)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at com.atlassian.core.filters.ServletContextThreadLocalFilter.doFilter(ServletContextThreadLocalFilter.java:21)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:217)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at com.atlassian.confluence.util.LoggingContextFilter.doFilter(LoggingContextFilter.java:46)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:217)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at com.atlassian.confluence.util.UserThreadLocalFilter.doFilter(UserThreadLocalFilter.java:44)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:217)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at com.atlassian.seraph.filter.SecurityFilter.doFilter(SecurityFilter.java:182)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:217)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at com.atlassian.seraph.filter.LoginFilter.doFilter(LoginFilter.java:159)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:217)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at com.atlassian.confluence.util.ClusterHeaderFilter.doFilter(ClusterHeaderFilter.java:35)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:217)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at com.atlassian.johnson.filters.JohnsonFilter.doFilter(JohnsonFilter.java:96)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:217)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at org.springframework.orm.hibernate.support.OpenSessionInViewFilter.doFilterInternal(OpenSessionInViewFilter.java:172)
      at com.atlassian.spring.filter.FlushingSpringSessionInViewFilter.doFilterInternal(FlushingSpringSessionInViewFilter.java:29)
      at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:217)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at com.atlassian.util.profiling.filters.ProfilingFilter.doFilter(ProfilingFilter.java:122)
      at com.atlassian.core.filters.ProfilingAndErrorFilter.doFilter(ProfilingAndErrorFilter.java:27)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:217)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at com.atlassian.confluence.util.RequestCacheThreadLocalFilter.doFilter(RequestCacheThreadLocalFilter.java:25)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:217)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at com.atlassian.core.filters.gzip.GzipFilter.doFilter(GzipFilter.java:61)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:217)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at com.atlassian.core.filters.AbstractEncodingFilter.doFilter(AbstractEncodingFilter.java:37)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:217)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at com.sun.dse.wikis.auth.SsoFilter.doFilter(SsoFilter.java:145)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:217)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185)
      at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275)
      at org.apache.catalina.core.StandardContextValve.invokeInternal(StandardContextValve.java:255)
      at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:188)
      at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:586)
      at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:556)
      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:187)
      at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:586)
      at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:556)
      at com.sun.webserver.connector.nsapi.NSAPIProcessor.service(NSAPIProcessor.java:160)
      Caused by: java.io.IOException: WEB8001: Write failed
      at com.sun.webserver.connector.nsapi.NSAPIResponseStream.doWrite(NSAPIResponseStream.java:61)
      at org.apache.coyote.Response.doWrite(Response.java:576)
      at org.apache.coyote.tomcat5.OutputBuffer.realWriteBytes(OutputBuffer.java:380)
      ... 99 more

            [CONFSERVER-9984] Superfluous exception logging from createrssfeed.action (java.io.IOException: WEB8001: Write failed)

            Updated logging as suggested.

            m@ (Inactive) added a comment - Updated logging as suggested.

            good news

            thanks,
            Igor

            Igor Minar added a comment - good news thanks, Igor

            Not really major, doesn't affect functionality at all but can make debugging harder as you have to sift through 1000's of "acceptable" exceptions in the logs.

            m@ (Inactive) added a comment - Not really major, doesn't affect functionality at all but can make debugging harder as you have to sift through 1000's of "acceptable" exceptions in the logs.

            Igor,

            The bug fix team's velocity was saturated and since this fix was very simple to apply, I have done it myself.

            I've logged a single line at info level like your patch, and logged the stack trace at debug level. This should cover the debugging scenarios and also clean up the logs quite a bit.

            The change should make 2.7, I will close this issue and mark the fix for version once all the tests pass and I've committed the change.

            Cheers
            Matt

            m@ (Inactive) added a comment - Igor, The bug fix team's velocity was saturated and since this fix was very simple to apply, I have done it myself. I've logged a single line at info level like your patch, and logged the stack trace at debug level. This should cover the debugging scenarios and also clean up the logs quite a bit. The change should make 2.7, I will close this issue and mark the fix for version once all the tests pass and I've committed the change. Cheers Matt

            Igor

            I agree and thought about this a bit.

            This error indicates that the server can't write back to the client after its done its work and is ready to transport.

            This us usually be because a client will close their window or timeout or something else as a result of user action.

            There are other situations, like networking issues, that could cause this problem, but as far as I can think of, they will all manifest themselves as errors on the client. At which point debugging can be enabled and the issue can be debugged. I think these cases are rarer (by a long shot) than the "client closing the app" situation, so my thinking is that spamming the logs at info level for a mostly-normal case, is a bad thing.

            This is by no means policy, so if you disagree please feel free to try and convince me otherwise.

            Cheers
            Matt

            m@ (Inactive) added a comment - Igor I agree and thought about this a bit. This error indicates that the server can't write back to the client after its done its work and is ready to transport. This us usually be because a client will close their window or timeout or something else as a result of user action. There are other situations, like networking issues, that could cause this problem, but as far as I can think of, they will all manifest themselves as errors on the client. At which point debugging can be enabled and the issue can be debugged. I think these cases are rarer (by a long shot) than the "client closing the app" situation, so my thinking is that spamming the logs at info level for a mostly-normal case, is a bad thing. This is by no means policy, so if you disagree please feel free to try and convince me otherwise. Cheers Matt

            Cool, the only thing I'm worried about is that if the IOException is thrown because of a different reason than client closing connection, we won't know about it.

            My brief research didn't reveal any way to handle such a case in a container agnostic manner.

            cheers,
            Igor

            Igor Minar added a comment - Cool, the only thing I'm worried about is that if the IOException is thrown because of a different reason than client closing connection, we won't know about it. My brief research didn't reveal any way to handle such a case in a container agnostic manner. cheers, Igor

            Igor

            Sorry it's taken me so long to respond. I had a quick look at the patch and like the look of it.

            One of my pet hates is superfluous logging so I really appreciate this one.

            I'll probably change the log level (to debug) but essentially keep it the same.

            I'll talk to the bug fix coordinator and update you when it's scheduled.

            Cheers
            Matt

            m@ (Inactive) added a comment - Igor Sorry it's taken me so long to respond. I had a quick look at the patch and like the look of it. One of my pet hates is superfluous logging so I really appreciate this one. I'll probably change the log level (to debug) but essentially keep it the same. I'll talk to the bug fix coordinator and update you when it's scheduled. Cheers Matt

            Igor Minar added a comment -

            Hi Matthew/Atlassians,

            Can you guys have a look at the patch and let us know if it is ok, or if you'd like to catch the exception at some other level?

            We are seeing this problem at wikis.sun.com quite often (several times per day, maybe even per hour) which causes our logs to grow a lot and making it difficult for us to search for other exceptions.

            cheers,
            Igor

            Igor Minar added a comment - Hi Matthew/Atlassians, Can you guys have a look at the patch and let us know if it is ok, or if you'd like to catch the exception at some other level? We are seeing this problem at wikis.sun.com quite often (several times per day, maybe even per hour) which causes our logs to grow a lot and making it difficult for us to search for other exceptions. cheers, Igor

              mjensen m@ (Inactive)
              28a437a2afce Alex Reid
              Affected customers:
              1 This affects my team
              Watchers:
              1 Start watching this issue

                Created:
                Updated:
                Resolved: