Richfaces 3.3.3 fileupload fails - in Front-end Apache web server setup - with error: (OS 10054) existing connection was forcibly closed by the remote host
We have a setup with Front-end Apache web server for JBoss application server. Tomcat Connector is used to connect the front-end web server and the JBoss application server.
UI env is Myfaces 1.2.6 with Tomahawk, Ricfaces 3.3.3
Please note that only from one of our client network, upload is failing only for large file sizes. (sometimes fails for above 50-100MB, and always fails for above 200MB)
The logs in apache web server shows:
x.x.x.x - - [09/Sep/2012:11:45:49 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4986 x.x.x.x - - [09/Sep/2012:11:45:50 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4986 x.x.x.x - - [09/Sep/2012:11:45:51 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4986 x.x.x.x - - [09/Sep/2012:11:45:17 -0400] "POST /myapp /ui/home.faces?_richfaces_upload_uid=0.9487435704432351& actionForm:upload=actionForm:upload&_richfaces_upload_file_indicator=true& AJAXREQUEST=actionForm:j_id45760 HTTP/1.1" 200 -
The error in JBoss console is:
2012-09-10 12:21:34,796 ERROR [org.apache.myfaces.shared_tomahawk.renderkit.html.HtmlGridRendererBase] (ajp-0.0.0.0-8009-1) Wrong columns attribute for PanelGrid headerTableId: -2147483648 2012-09-10 12:22:21,981 ERROR [org.apache.myfaces.lifecycle.PhaseListenerManager] (ajp-0.0.0.0-8009-2) Exception in PhaseListener RESTORE_VIEW 1 beforePhase. org.ajax4jsf.exception.FileUploadException: IO Error parsing multipart request at org.ajax4jsf.request.MultipartRequest.parseRequest(MultipartRequest.java:388) at org.richfaces.component.FileUploadPhaselistener.beforePhase(FileUploadPhaselistener.java:63) at org.apache.myfaces.lifecycle.PhaseListenerManager.informPhaseListenersBefore(PhaseListenerManager.java:73) at org.apache.myfaces.lifecycle.LifecycleImpl.executePhase(LifecycleImpl.java:93) at org.apache.myfaces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:76) at javax.faces.webapp.FacesServlet.service(FacesServlet.java:265) at org.apache.myfaces.webapp.MyFacesServlet.service(MyFacesServlet.java:103) at com.mycom.myapp.FacesErrorHandlingServlet.service(FacesErrorHandlingServlet.java:44) at sun.reflect.GeneratedMethodAccessor580.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:275) at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:274) at java.security.AccessController.doPrivileged(Native Method) at javax.security.auth.Subject.doAsPrivileged(Subject.java:517) at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:307) at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:167) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:283) at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:56) at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:189) at java.security.AccessController.doPrivileged(Native Method) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185) at org.apache.myfaces.webapp.filter.ExtensionsFilter.doFilter(ExtensionsFilter.java:301) at sun.reflect.GeneratedMethodAccessor461.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:275) at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:274) at java.security.AccessController.doPrivileged(Native Method) at javax.security.auth.Subject.doAsPrivileged(Subject.java:517) at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:307) at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:248) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:230) at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:56) at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:189) at java.security.AccessController.doPrivileged(Native Method) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185) at com.mycom.myapp.FacesSessionFilter.process(FacesSessionFilter.java:57) at com.mycom.myapp.SessionFilter.doFilter(SessionFilter.java:133) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:275) at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:274) at java.security.AccessController.doPrivileged(Native Method) at javax.security.auth.Subject.doAsPrivileged(Subject.java:517) at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:307) at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:248) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:230) at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:56) at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:189) at java.security.AccessController.doPrivileged(Native Method) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185) at org.ajax4jsf.webapp.BaseXMLFilter.doXmlFilter(BaseXMLFilter.java:206) at org.ajax4jsf.webapp.BaseFilter.handleRequest(BaseFilter.java:290) at org.ajax4jsf.webapp.BaseFilter.processUploadsAndHandleRequest(BaseFilter.java:367) at org.ajax4jsf.webapp.BaseFilter.doFilter(BaseFilter.java:515) at sun.reflect.GeneratedMethodAccessor279.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:275) at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:274) at java.security.AccessController.doPrivileged(Native Method) at javax.security.auth.Subject.doAsPrivileged(Subject.java:517) at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:307) at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:248) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:230) at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:56) at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:189) at java.security.AccessController.doPrivileged(Native Method) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185) at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96) at sun.reflect.GeneratedMethodAccessor254.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:275) at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:274) at java.security.AccessController.doPrivileged(Native Method) at javax.security.auth.Subject.doAsPrivileged(Subject.java:517) at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:307) at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:248) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:230) at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:56) at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:189) at java.security.AccessController.doPrivileged(Native Method) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:185) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:190) at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:92) at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126) at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330) at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:436) at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:384) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) Caused by: java.io.IOException: Request data cannot be read at org.ajax4jsf.request.MultipartRequest.readData(MultipartRequest.java:341) at org.ajax4jsf.request.MultipartRequest.readNext(MultipartRequest.java:210) at org.ajax4jsf.request.MultipartRequest.parseRequest(MultipartRequest.java:382) ... 101 more
I am not sure if
1. firewalls in that country site can give this problem or
2. apache / jboss configuration (req timeout etc) - but then upload works from other country sites.
3. web.xml settings where MyFacesExtensionsFilter and Ajax4jsf Filter exists - but then again upload works from other country sites.
A note about Richfaces fileupload component client behavior: It is trying multiple times to upload the same file. This is evident from the
progress bar, where it tries to upload some bytes, fails, again starts from the start, again fails...this pattern is also matches with
apache server logs as shown below. Finally, after 5-10 tries, upload fails with "Transfer error occurred".
x.x.x.x - - - [09/Sep/2012:13:51:52 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4986 x.x.x.x - - - [09/Sep/2012:13:50:59 -0400] "POST /myapp /ui/home.faces?_richfaces_upload_uid=0.21159051128917716& actionForm:upload=actionForm:upload&_richfaces_upload_file_indicator=true& AJAXREQUEST=actionForm:j_id437 HTTP/1.1" 200 - x.x.x.x - - - [09/Sep/2012:13:51:53 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:51:55 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x -- - [09/Sep/2012:13:51:56 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:51:57 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:51:58 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:51:59 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:00 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:01 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:02 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:04 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:05 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:06 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:07 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:08 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:09 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:10 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:12 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:13 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:14 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:15 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:16 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:51:53 -0400] "POST /myapp /ui/home.faces?_richfaces_upload_uid=0.21159051128917716& actionForm:upload=actionForm:upload&_richfaces_upload_file_indicator=true& AJAXREQUEST=actionForm:j_id437 HTTP/1.1" 200 - x.x.x.x - - - [09/Sep/2012:13:52:17 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:18 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:19 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x -- - [09/Sep/2012:13:52:21 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:22 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x -- - [09/Sep/2012:13:52:23 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:24 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:25 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:26 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:27 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:29 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:30 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:31 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:32 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:33 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:34 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:35 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:37 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - - [09/Sep/2012:13:52:38 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x -- - [09/Sep/2012:13:52:16 -0400] "POST /myapp /ui/home.faces?_richfaces_upload_uid=0.21159051128917716& actionForm:upload=actionForm:upload&_richfaces_upload_file_indicator=true& AJAXREQUEST=actionForm:j_id437 HTTP/1.1" 200 - x.x.x.x - - - [09/Sep/2012:13:52:39 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984 x.x.x.x - - [09/Sep/2012:13:52:40 -0400] "POST /myapp/ui/home.faces HTTP/1.1" 200 4984
Please share any pointers or workarounds that I can try, and that will be very helpful.
Thanks very much in advance.
Best Regards, Kumar.
| @update : After running apache with debug logs, the error log shows the upload for a single file of size 200MB. In this case, 5 tries happened to upload, in each try, the error message is [client x.x.x.x] (OS 10054)An existing connection was forcibly closed by the remote host. : core_output_filter: writing data to the network, but finally upload failed. Please share any idea where to fix this issue. Thank you in advance.
[Thu Sep 13 01:52:54 2012] [info] removed PID file C:/Program Files (x86)/Apache Software Foundation/Apache2.2/logs/httpd.pid (pid=8060) [Thu Sep 13 01:55:57 2012] [notice] Apache/2.2.22 (Win32) mod_jk/1.2.31 configured -- resuming normal operations . . . [Thu Sep 13 01:55:57 2012] [notice] Child 7864: Acquired the start mutex. [Thu Sep 13 01:55:57 2012] [notice] Child 7864: Starting 64 worker threads. [Thu Sep 13 01:55:57 2012] [notice] Child 7864: Starting thread to listen on port 80. [Thu Sep 13 01:58:19 2012] [info] [client x.x.x.x] (OS 10054)An existing connection was forcibly closed by the remote host. : core_output_filter: writing data to the network [Thu Sep 13 02:00:45 2012] [info] [client x.x.x.x] (OS 10054)An existing connection was forcibly closed by the remote host. : core_output_filter: writing data to the network [Thu Sep 13 02:01:20 2012] [info] [client x.x.x.x] (OS 10054)An existing connection was forcibly closed by the remote host. : core_output_filter: writing data to the network [Thu Sep 13 02:02:10 2012] [info] [client x.x.x.x] (OS 10054)An existing connection was forcibly closed by the remote host. : core_output_filter: writing data to the network [Thu Sep 13 02:02:47 2012] [info] [client x.x.x.x] (OS 10054)An existing connection was forcibly closed by the remote host. : core_output_filter: writing data to the network [Thu Sep 13 02:03:19 2012] [info] [client x.x.x.x] (OS 10054)An existing connection was forcibly closed by the remote host. : core_output_filter: writing data to the network |