Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

File Upload: Intermittent Failure to upload files on dataset create using direct to s3 #6829

Closed
kcondon opened this issue Apr 16, 2020 · 7 comments · Fixed by #6857
Closed

Comments

@kcondon
Copy link
Contributor

kcondon commented Apr 16, 2020

This had been working but now is failing consistently but with different symptoms. Uploading files using direct to s3 works if the dataset is already created but fails if it is while creating the dataset.

There are two types of failures observed:

  1. The files remain stuck with progress bars, not added to list, error in logs indicate:
[2020-04-16T13:52:40.163-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=52 _ThreadName=jk-connector(1)] [timeMillis: 1587059560163] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: D7269DC825F6321A; S3 Extended Request ID: KlwTlLRB8NSmNm7RqzV0XvhKyHVKsjMlp+hPWLifMX0bm0xM8dcGN8QSGrGsU4P+th7Mtq4uLX4=)]]
  1. The files complete upload, appear in list but when save, it fails to add the files, error in server log:

[2020-04-16T13:59:08.233-0400] [glassfish 4.1] [SEVERE] [] [javax.enterprise.resource.webcontainer.jsf.context] [tid: _ThreadID=53 _ThreadName=jk-connector(2)] [timeMillis: 1587059948233] [levelValue: 1000] [[
  java.lang.ArrayIndexOutOfBoundsException: -1
        at java.util.ArrayList.fastRemove(ArrayList.java:550)
        at java.util.ArrayList.remove(ArrayList.java:533)
        at javax.faces.component.ComponentStateHelper.removeFromList(ComponentStateHelper.java:396)
        at javax.faces.component.ComponentStateHelper.remove(ComponentStateHelper.java:232)
        at javax.faces.component.UIComponentBase$AttributesMap.remove(UIComponentBase.java:2498)
        at javax.faces.component.UIComponentBase.setParent(UIComponentBase.java:450)
        at javax.faces.component.UIComponentBase$ChildrenList.add(UIComponentBase.java:2680)
        at javax.faces.component.UIComponentBase$ChildrenList.add(UIComponentBase.java:2652)
        at com.sun.faces.facelets.tag.jsf.ComponentSupport.addComponent(ComponentSupport.java:489)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.addComponentToView(ComponentTagHandlerDelegateImpl.java:350)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.addComponentToView(ComponentTagHandlerDelegateImpl.java:333)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:222)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:203)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:203)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at com.sun.faces.facelets.tag.ui.CompositionHandler.apply(CompositionHandler.java:194)
        at com.sun.faces.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:93)
        at com.sun.faces.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:87)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:312)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:371)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:350)
        at com.sun.faces.facelets.impl.DefaultFaceletContext.includeFacelet(DefaultFaceletContext.java:199)
        at com.sun.faces.facelets.tag.ui.IncludeHandler.apply(IncludeHandler.java:124)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:203)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:203)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at com.sun.faces.facelets.tag.ui.DefineHandler.applyDefinition(DefineHandler.java:106)
        at com.sun.faces.facelets.tag.ui.CompositionHandler.apply(CompositionHandler.java:206)
        at com.sun.faces.facelets.impl.DefaultFaceletContext$TemplateManager.apply(DefaultFaceletContext.java:395)
        at com.sun.faces.facelets.impl.DefaultFaceletContext.includeDefinition(DefaultFaceletContext.java:366)
        at com.sun.faces.facelets.tag.ui.InsertHandler.apply(InsertHandler.java:111)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:203)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at com.sun.faces.facelets.tag.jsf.core.ViewHandler.apply(ViewHandler.java:225)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at com.sun.faces.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:93)
        at com.sun.faces.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:87)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:312)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:371)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:350)
        at com.sun.faces.facelets.impl.DefaultFaceletContext.includeFacelet(DefaultFaceletContext.java:199)
        at com.sun.faces.facelets.tag.ui.CompositionHandler.apply(CompositionHandler.java:174)
        at com.sun.faces.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:93)
        at com.sun.faces.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:87)
        at com.sun.faces.facelets.impl.DefaultFacelet.apply(DefaultFacelet.java:161)
        at com.sun.faces.application.view.FaceletViewHandlingStrategy.buildView(FaceletViewHandlingStrategy.java:990)
        at com.sun.faces.application.view.FaceletViewHandlingStrategy.restoreView(FaceletViewHandlingStrategy.java:579)
        at com.sun.faces.application.view.MultiViewHandler.restoreView(MultiViewHandler.java:150)
        at javax.faces.application.ViewHandlerWrapper.restoreView(ViewHandlerWrapper.java:353)
        at org.omnifaces.viewhandler.RestorableViewHandler.restoreView(RestorableViewHandler.java:66)
        at org.ocpsoft.rewrite.faces.RewriteViewHandler.restoreView(RewriteViewHandler.java:102)
        at javax.faces.application.ViewHandlerWrapper.restoreView(ViewHandlerWrapper.java:353)
        at com.sun.faces.lifecycle.RestoreViewPhase.execute(RestoreViewPhase.java:197)
        at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:101)
        at com.sun.faces.lifecycle.RestoreViewPhase.doPhase(RestoreViewPhase.java:121)
        at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:198)
        at javax.faces.webapp.FacesServlet.service(FacesServlet.java:646)
        at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1682)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:344)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.glassfish.tyrus.servlet.TyrusServletFilter.doFilter(TyrusServletFilter.java:295)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.ocpsoft.rewrite.servlet.RewriteFilter.doFilter(RewriteFilter.java:226)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:316)
        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:412)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:282)
        at com.sun.enterprise.v3.services.impl.ContainerMapper$HttpHandlerCallable.call(ContainerMapper.java:459)
        at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:167)
        at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:201)
        at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:175)
        at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:235)
        at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:284)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:201)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:133)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
        at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:561)
        at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:117)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:56)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:137)
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:565)
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:545)
        at java.lang.Thread.run(Thread.java:748)
]]

Other, possibly related server log errors:


[2020-04-16T14:06:27.715-0400] [glassfish 4.1] [SEVERE] [] [edu.harvard.iq.dataverse.EditDatafilesPage] [tid: _ThreadID=138 _ThreadName=jk-connector(3)] [timeMillis: 1587060387715] [levelValue: 1000] [[
  Failed to create DataFile for file 50by1000 (5) (2).dta: Cannot get S3 object 10.70122/FK2/A3ZRZE/171842aca02-85dcc8ef591c (Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 5634ED8FB499C089; S3 Extended Request ID: 4hzhQfoypb4xuMX5WDVBm4BUni3rnQdJRgHZzcvJJuWqjjQD0jxAQ0Hmg3Chcyr7Aa6zQckvIGI=))]]

[2020-04-16T14:06:27.864-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.ImageThumbConverter] [tid: _ThreadID=52 _ThreadName=jk-connector(1)] [timeMillis: 1587060387864] [levelValue: 900] [[
  Failed to read in an image from /usr/local/glassfish4/glassfish/domains/domain1/files/temp/s31://iqssqa:171842bacc2-62bf88ceb989: Can't read input file!]]

[2020-04-16T14:06:58.321-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.DataAccess] [tid: _ThreadID=52 _ThreadName=jk-connector(1)] [timeMillis: 1587060418321] [levelValue: 900] [[
  Could not find storage driver for: s3://iqssqa:16ea3cbba0c-638d1e50ec5e]]

[2020-04-16T14:06:58.322-0400] [glassfish 4.1] [SEVERE] [] [] [tid: _ThreadID=52 _ThreadName=Thread-9] [timeMillis: 1587060418322] [levelValue: 1000] [[
  java.io.IOException: getDataAccessObject: Unsupported storage method.
        at edu.harvard.iq.dataverse.dataaccess.DataAccess.getStorageIO(DataAccess.java:88)
        at edu.harvard.iq.dataverse.dataaccess.DataAccess.getStorageIO(DataAccess.java:52)
        at edu.harvard.iq.dataverse.DataFile.getStorageIO(DataFile.java:598)
        at edu.harvard.iq.dataverse.FilePage.getPublicDownloadUrl(FilePage.java:922)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at javax.el.BeanELResolver.getValue(BeanELResolver.java:363)
        at com.sun.faces.el.DemuxCompositeELResolver._getValue(DemuxCompositeELResolver.java:176)
        at com.sun.faces.el.DemuxCompositeELResolver.getValue(DemuxCompositeELResolver.java:203)
        at com.sun.el.parser.AstValue.getValue(AstValue.java:140)
        at com.sun.el.parser.AstValue.getValue(AstValue.java:204)
        at com.sun.el.ValueExpressionImpl.getValue(ValueExpressionImpl.java:226)
        at org.jboss.weld.el.WeldValueExpression.getValue(WeldValueExpression.java:50)
        at com.sun.faces.facelets.el.TagValueExpression.getValue(TagValueExpression.java:109)
        at javax.faces.component.ComponentStateHelper.eval(ComponentStateHelper.java:194)
        at javax.faces.component.ComponentStateHelper.eval(ComponentStateHelper.java:182)
        at javax.faces.component.UIOutput.getValue(UIOutput.java:174)
        at com.sun.faces.renderkit.html_basic.HtmlBasicInputRenderer.getValue(HtmlBasicInputRenderer.java:205)
        at com.sun.faces.renderkit.html_basic.HtmlBasicRenderer.getCurrentValue(HtmlBasicRenderer.java:355)
        at com.sun.faces.renderkit.html_basic.HtmlBasicRenderer.encodeEnd(HtmlBasicRenderer.java:164)
        at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:919)
        at com.sun.faces.renderkit.html_basic.HtmlBasicRenderer.encodeRecursive(HtmlBasicRenderer.java:312)
        at com.sun.faces.renderkit.html_basic.PassthroughRenderer.encodeChildren(PassthroughRenderer.java:104)
        at javax.faces.component.UIComponentBase.encodeChildren(UIComponentBase.java:889)
        at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1856)
        at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1859)
        at org.primefaces.component.tabview.TabViewRenderer.encodeTabContent(TabViewRenderer.java:345)
        at org.primefaces.component.tabview.TabViewRenderer.encodeContents(TabViewRenderer.java:301)
        at org.primefaces.component.tabview.TabViewRenderer.encodeMarkup(TabViewRenderer.java:143)
        at org.primefaces.component.tabview.TabViewRenderer.encodeEnd(TabViewRenderer.java:82)
        at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:919)
        at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1863)
        at javax.faces.render.Renderer.encodeChildren(Renderer.java:176)
        at javax.faces.component.UIComponentBase.encodeChildren(UIComponentBase.java:889)
        at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1856)
        at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1859)
        at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1859)
        at com.sun.faces.application.view.FaceletViewHandlingStrategy.renderView(FaceletViewHandlingStrategy.java:456)
        at com.sun.faces.application.view.MultiViewHandler.renderView(MultiViewHandler.java:133)
        at javax.faces.application.ViewHandlerWrapper.renderView(ViewHandlerWrapper.java:337)
        at org.ocpsoft.rewrite.faces.RewriteViewHandler.renderView(RewriteViewHandler.java:196)
        at javax.faces.application.ViewHandlerWrapper.renderView(ViewHandlerWrapper.java:337)
        at com.sun.faces.lifecycle.RenderResponsePhase.execute(RenderResponsePhase.java:120)
        at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:101)
        at com.sun.faces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:219)
        at javax.faces.webapp.FacesServlet.service(FacesServlet.java:647)
        at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1682)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:344)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.glassfish.tyrus.servlet.TyrusServletFilter.doFilter(TyrusServletFilter.java:295)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.ocpsoft.rewrite.servlet.RewriteFilter.doFilter(RewriteFilter.java:226)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:316)
        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:412)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:282)
        at com.sun.enterprise.v3.services.impl.ContainerMapper$HttpHandlerCallable.call(ContainerMapper.java:459)
        at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:167)
        at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:201)
        at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:175)
        at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:235)
        at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:284)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:201)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:133)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
        at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:561)
        at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:117)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:56)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:137)
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:565)
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:545)
        at java.lang.Thread.run(Thread.java:748)]]
@djbrooke
Copy link
Contributor

Thanks @kcondon. @qqmyers - any capacity to work on this? If not, we'll bring it into sprint soon.

@qqmyers
Copy link
Member

qqmyers commented Apr 17, 2020

Not sure I can debug unless I can reproduce it. A couple thoughts to start:
If things fail with stuck progress bars - this indicates some call from the browser failed and the browser console should be able to tell you which one. That info should help. If the bar is stuck at 50% or less, the problem is likely with the call to S3. If it is stuck at ~100%, it's the call to Dataverse that is failing. It's possible that not calls to Dataverse are tied into the error handling so knowing what fails will help fix that.

On the server side, the 'Retrying after:' message itself is not fatal. The code retries up to 20 times, every three seconds to see if S3 is reporting that the file exists yet (there can be a delay in us-east1 between when the file is created on S3 and when calls to get it/it's metadata will succeed. If that delay is greater than one minute, it's surprising. The log should show 20 retries if that's the case though.)

The 'Cannot get S3 object ...' line could be caused by a failure from having 20 retries fail, but the next line 'Could not find storage driver for: s3://iqssqa:16ea3cbba0c-638d1e50ec5e' might suggest another cause. That happens when the code strips the beginning 's3' off and can't find the storage type - looking for the dataverse.files.s3.type=s3 jvm option. Could that not be set on this instance?

@kcondon
Copy link
Contributor Author

kcondon commented Apr 17, 2020

@qqmyers I can retest with your suggestions. This is the same box and config I used to do the original multistore testing.

  1. progress bars are stuck both half way and full, will get console output
    -First test, all 3 files stuck at 100% progress with this in console
Uploading 50by1000 (5) (2) (2).dta as s31://iqssqa:1718972778a-64412264208d to https://iqssqa.s3.amazonaws.com/10.70122/FK2/CQVNCN/1718972778a-64412264208d?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Date=20200417T184153Z&X-Amz-SignedHeaders=host%3Bx-amz-tagging&X-Amz-Expires=3599&X-Amz-Credential=AKIAIODRE3USX25R5IAA%2F20200417%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Signature=4f0b47d335f2f01dd134c4381d6348e4ef8edcbeb0d0f800703385e550206f9c
fileupload.js.xhtml:84 Uploading cheese1 (1) (1) (1) (1) (1).jpg as s31://iqssqa:17189727772-571490eb789b to https://iqssqa.s3.amazonaws.com/10.70122/FK2/F3EUCB/17189727772-571490eb789b?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Date=20200417T184153Z&X-Amz-SignedHeaders=host%3Bx-amz-tagging&X-Amz-Expires=3600&X-Amz-Credential=AKIAIODRE3USX25R5IAA%2F20200417%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Signature=1ac2bbf3769c29caed7d505f582ae4f4a6224e91be07965eea5e612f76f998bf
fileupload.js.xhtml:84 Uploading file1 (6) (1) (1) (1) (2) (1).txt as s31://iqssqa:17189727774-53b3a96a7876 to https://iqssqa.s3.amazonaws.com/10.70122/FK2/CQVNCN/17189727774-53b3a96a7876?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Date=20200417T184153Z&X-Amz-SignedHeaders=host%3Bx-amz-tagging&X-Amz-Expires=3599&X-Amz-Credential=AKIAIODRE3USX25R5IAA%2F20200417%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Signature=2f9cbebf97bf7017112185ef1aa352c1b5df5e87a26fcfa112bfb457051b9d73
fileupload.js.xhtml:139 S3 Upload complete for file1 (6) (1) (1) (1) (2) (1).txt : s31://iqssqa:17189727774-53b3a96a7876
fileupload.js.xhtml:139 S3 Upload complete for cheese1 (1) (1) (1) (1) (1).jpg : s31://iqssqa:17189727772-571490eb789b
fileupload.js.xhtml:139 S3 Upload complete for 50by1000 (5) (2) (2).dta : s31://iqssqa:1718972778a-64412264208d
fileupload.js.xhtml:219 0 : 1 : 3 : 0
fileupload.js.xhtml:219 0 : 2 : 3 : 0

Correction: needed to wait longer than expected (no indication it was doing something) but was doing the 20 retries and then 2 of the 3 files eventually uploaded.
One failed.
Console added these lines:, note did not include all the child events..

jquery.js.xhtml?ln=primefaces&v=8.0:2 [Deprecation] Synchronous XMLHttpRequest on the main thread is deprecated because of its detrimental effects to the end user's experience. For more help, check https://xhr.spec.whatwg.org/.
VM2627:1 dropins.js included more than once

server log looked like this:

[2020-04-17T14:41:57.725-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148917725] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: E64FF0902F758FFF; S3 Extended Request ID: pGH/6fV4Q6nmd8pBJ1a6OvRUQCp/vDkGm3EQGcKSArl8Cu0sJ2Ty5XLkk6y8MlFlUXn7uER7WkM=)]]

[2020-04-17T14:42:00.753-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148920753] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 095DB61690C49D93; S3 Extended Request ID: XXflmioMO/6QdEnFeI9ZYgucvzru9hZhYV9rr6jWSfTNj9ioGqG9ZiLJ/FfKLef2GcTcU/hRzqI=)]]

[2020-04-17T14:42:03.829-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148923829] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 602FBECF661D4A63; S3 Extended Request ID: sms+2+5uSuzlebt71aK6NHC7fZJkRuj3oRdwdVH3VDdekaE7iKOIwZigZ49D4Z9LnhqnRDxUC+Y=)]]

[2020-04-17T14:42:06.854-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148926854] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 6CBFAE4162A6D6A2; S3 Extended Request ID: oFB42cDBazQ251mQDI8mT8PycOh5JykMFl43v1y4eQynOuzU6Pwex+9t8l/i1QZifUbo6S+fiDM=)]]

[2020-04-17T14:42:09.880-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148929880] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 78467D24118541B0; S3 Extended Request ID: za+18/WYbUTIxHxY+Xh13FxJ2qkMM1cfYXCdy0bDfTMy44g+oLIaARyTCTznd7SJwc3ZRvQ/BTQ=)]]

[2020-04-17T14:42:12.900-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148932900] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: AD551DA43FB4702B; S3 Extended Request ID: jEX9jsApYEQEcF05JidlzBQIJkJD1pQ04WKfome1mxTGe4n0DRRwlEXF/JW2NLT3KkYIQAIxTC8=)]]

[2020-04-17T14:42:15.921-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148935921] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: AF88ABDB8540CC20; S3 Extended Request ID: ALfDJNw71n+MwPE720ZDkOamTL+r7XXTrV9cDpfUQTUOIVuTfXIChDv1gi7AAHVLbwKimKcWf0I=)]]

[2020-04-17T14:42:19.304-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148939304] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: AC09D49D72448F55; S3 Extended Request ID: xsXzOMdH5LpwKdqnOq21UHxIGhbiGyAP6+Z0/Mh+sBVKYb25khyTRNIyGTywagP+80Pqw15Ds8A=)]]

[2020-04-17T14:42:22.328-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148942328] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 5684445963FD5B46; S3 Extended Request ID: DDwmIqz+UB+jw1jtybCbfOruU79+8iUgxaRZILLqJQXN53MGN5Hfrb3skfHGfZ1zZaKvUBci18k=)]]

[2020-04-17T14:42:25.348-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148945348] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: CF5DD3CA91467020; S3 Extended Request ID: Nze6Nkoz2c89u5TyobLgcUNYHYWFxvAjjMBaEw/HAPsd9RC2/RRjCOp2lCTFUF7qfeXG9sAgOa8=)]]

[2020-04-17T14:42:28.370-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148948370] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 365F2E425792F418; S3 Extended Request ID: pK0trUe1zfPUfrnE+2Tcur+jtWlfgCUJZ7KCHWz8/iZbMl7RMDAFUVwOCzJNgQgtbx8+fDoQc0w=)]]

[2020-04-17T14:42:31.390-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148951390] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 408F587BF19BDDF8; S3 Extended Request ID: ULyF8ZFGW8zicsipa24CXlFMHTPuqBKGOaJ3+qHkp0aR1C5wMrQ4BSi5XJAs6sl0T/6BMQfH+RM=)]]

[2020-04-17T14:42:34.410-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148954410] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 65F2962829989740; S3 Extended Request ID: 9eOycgilDsJDLnbBTdFmOf+LZ49ywR2t5PYPN1mKVn+pLegOui2q1J3RDmHdzAMPofGfxlztAtg=)]]

[2020-04-17T14:42:37.432-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148957432] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: A6DD81EE4444262C; S3 Extended Request ID: B0bPwh5vHYq//UxBNL/CMKiaGijtrlncfE7hGSp+1KPzWyzSdbChKtusqiqNzN2Dyx2ZjY5H/8Y=)]]

[2020-04-17T14:42:40.451-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148960451] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: AA447C8197D69345; S3 Extended Request ID: tjU7Y9tXhw0qcywEVIQmTSfnUPw9ABmHXhEOQ8BFipFoBWKH7Jc04nMYBQeSXbr1zg7LtB5azgI=)]]

[2020-04-17T14:42:43.470-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148963470] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 54A799335A6AC987; S3 Extended Request ID: TVWp7D+Fqo9onxhvl8DexH219cln5SSJ3KGzZs+OrkoBAVEkBuNO8A/FJ5ZWaTVnAMneI7q1QO0=)]]

[2020-04-17T14:42:46.490-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148966490] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: C18EFAF0DA2A1E08; S3 Extended Request ID: ZywTjjcqUwb8TfaiVq1/JuJGt4WSMdrJeOjAAEhbWj0S8aWnVkYgnPP31kkFJsFby7ifBgVMov4=)]]

[2020-04-17T14:42:49.510-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148969510] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 865ACCD8BBE5DDED; S3 Extended Request ID: CUYkNJBOmTLFI4trqYV7u+iO7P16hircBpnravfMEvm6C5gcUZzR13JlunNHAYff088iB5In0Ko=)]]

[2020-04-17T14:42:52.534-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.S3AccessIO] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148972534] [levelValue: 900] [[
  Retrying after: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 48E31C1BD0B07730; S3 Extended Request ID: FRnrAnn+L4L9MWD+N4azloY5txU1Czbf+lyund0118Fk3KVXmcj3EJU9A9zwgE1TkmYlIsyUKL8=)]]

[2020-04-17T14:42:52.555-0400] [glassfish 4.1] [SEVERE] [] [edu.harvard.iq.dataverse.EditDatafilesPage] [tid: _ThreadID=55 _ThreadName=jk-connector(2)] [timeMillis: 1587148972555] [levelValue: 1000] [[
  Failed to create DataFile for file cheese1 (1) (1) (1) (1) (1).jpg: Cannot get S3 object 10.70122/FK2/CQVNCN/17189727772-571490eb789b (Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: DA8B6A74285DE734; S3 Extended Request ID: hI0iIftQIuUmXI/w+f/xoGxYT81j7lqxp2mSHhD7w97888nfjoe8uM/z7NiOEKH0l0U7jmpzS4s=))]]

-Second test, it worked as expected
-Third test, two files stuck at 100% progress, 1 at 0%, never recovered, unlike test1, error thrown in log, no retries displayed:


[2020-04-17T14:58:26.022-0400] [glassfish 4.1] [WARNING] [jsf.externalcontext.no.mime.type.found] [javax.enterprise.resource.webcontainer.jsf.context] [tid: _ThreadID=54 _ThreadName=jk-connector(1)] [timeMillis: 1587149906022] [levelValue: 900] [[
  JSF1091: No mime type could be found for file bs/css/bootstrap.min.css.map.  To resolve this, add a mime-type mapping to the applications web.xml.]]

[2020-04-17T14:59:09.347-0400] [glassfish 4.1] [SEVERE] [] [javax.enterprise.resource.webcontainer.jsf.context] [tid: _ThreadID=151 _ThreadName=jk-connector(3)] [timeMillis: 1587149949347] [levelValue: 1000] [[
  java.lang.NullPointerException
        at javax.faces.component.UIComponentBase.doPreRemoveProcessing(UIComponentBase.java:1935)
        at javax.faces.component.UIComponentBase.setParent(UIComponentBase.java:435)
        at javax.faces.component.UIComponentBase$ChildrenList.remove(UIComponentBase.java:2743)
        at javax.faces.component.UIComponentBase$ChildrenList.remove(UIComponentBase.java:2652)
        at javax.faces.component.UIComponentBase.eraseParent(UIComponentBase.java:543)
        at javax.faces.component.UIComponentBase.access$500(UIComponentBase.java:99)
        at javax.faces.component.UIComponentBase$ChildrenList.add(UIComponentBase.java:2678)
        at javax.faces.component.UIComponentBase$ChildrenList.add(UIComponentBase.java:2652)
        at com.sun.faces.facelets.tag.jsf.ComponentSupport.addComponent(ComponentSupport.java:489)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.addComponentToView(ComponentTagHandlerDelegateImpl.java:350)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.addComponentToView(ComponentTagHandlerDelegateImpl.java:333)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:222)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:203)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:203)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at com.sun.faces.facelets.tag.ui.CompositionHandler.apply(CompositionHandler.java:194)
        at com.sun.faces.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:93)
        at com.sun.faces.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:87)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:312)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:371)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:350)
        at com.sun.faces.facelets.impl.DefaultFaceletContext.includeFacelet(DefaultFaceletContext.java:199)
        at com.sun.faces.facelets.tag.ui.IncludeHandler.apply(IncludeHandler.java:124)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:203)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:203)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at com.sun.faces.facelets.tag.ui.DefineHandler.applyDefinition(DefineHandler.java:106)
        at com.sun.faces.facelets.tag.ui.CompositionHandler.apply(CompositionHandler.java:206)
        at com.sun.faces.facelets.impl.DefaultFaceletContext$TemplateManager.apply(DefaultFaceletContext.java:395)
        at com.sun.faces.facelets.impl.DefaultFaceletContext.includeDefinition(DefaultFaceletContext.java:366)
        at com.sun.faces.facelets.tag.ui.InsertHandler.apply(InsertHandler.java:111)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:203)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at com.sun.faces.facelets.tag.jsf.core.ViewHandler.apply(ViewHandler.java:225)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:95)
        at com.sun.faces.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:93)
        at com.sun.faces.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:87)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:312)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:371)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:350)
        at com.sun.faces.facelets.impl.DefaultFaceletContext.includeFacelet(DefaultFaceletContext.java:199)
        at com.sun.faces.facelets.tag.ui.CompositionHandler.apply(CompositionHandler.java:174)
        at com.sun.faces.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:93)
        at com.sun.faces.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:87)
        at com.sun.faces.facelets.impl.DefaultFacelet.apply(DefaultFacelet.java:161)
        at com.sun.faces.application.view.FaceletViewHandlingStrategy.buildView(FaceletViewHandlingStrategy.java:990)
        at com.sun.faces.application.view.FaceletViewHandlingStrategy.restoreView(FaceletViewHandlingStrategy.java:579)
        at com.sun.faces.application.view.MultiViewHandler.restoreView(MultiViewHandler.java:150)
        at javax.faces.application.ViewHandlerWrapper.restoreView(ViewHandlerWrapper.java:353)
        at org.omnifaces.viewhandler.RestorableViewHandler.restoreView(RestorableViewHandler.java:66)
        at org.ocpsoft.rewrite.faces.RewriteViewHandler.restoreView(RewriteViewHandler.java:102)
        at javax.faces.application.ViewHandlerWrapper.restoreView(ViewHandlerWrapper.java:353)
        at com.sun.faces.lifecycle.RestoreViewPhase.execute(RestoreViewPhase.java:197)
        at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:101)
        at com.sun.faces.lifecycle.RestoreViewPhase.doPhase(RestoreViewPhase.java:121)
        at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:198)
        at javax.faces.webapp.FacesServlet.service(FacesServlet.java:646)
        at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1682)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:344)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.glassfish.tyrus.servlet.TyrusServletFilter.doFilter(TyrusServletFilter.java:295)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.ocpsoft.rewrite.servlet.RewriteFilter.doFilter(RewriteFilter.java:226)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:316)
        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:412)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:282)
        at com.sun.enterprise.v3.services.impl.ContainerMapper$HttpHandlerCallable.call(ContainerMapper.java:459)
        at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:167)
        at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:201)
        at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:175)
        at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:235)
        at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:284)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:201)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:133)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
        at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:561)
        at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:117)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:56)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:137)
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:565)
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:545)
        at java.lang.Thread.run(Thread.java:748)
]]

[2020-04-17T14:59:10.433-0400] [glassfish 4.1] [WARNING] [] [edu.harvard.iq.dataverse.dataaccess.ImageThumbConverter] [tid: _ThreadID=54 _ThreadName=jk-connector(1)] [timeMillis: 1587149950433] [levelValue: 900] [[
  Failed to read in an image from /usr/local/glassfish4/glassfish/domains/domain1/files/temp/s31://iqssqa:171898249ed-984b97586944: Can't read input file!]]

console for above test 3 failure:

DevTools failed to parse SourceMap: https://dvn-build.hmdc.harvard.edu/javax.faces.resource/bs/css/bootstrap.min.css.map.xhtml
DevTools failed to parse SourceMap: https://dvn-build.hmdc.harvard.edu/javax.faces.resource/bs/css/bootstrap-theme.min.css.map.xhtml
dataset.xhtml?ownerId=1:1 [DOM] Found 5 elements with non-unique id #j_id1:javax.faces.ViewState:0: (More info: https://goo.gl/9p2vKq) <input type=​"hidden" name=​"javax.faces.ViewState" id=​"j_id1:​javax.faces.ViewState:​0" value=​"-8409704188153521068:​-2702627544539744037" autocomplete=​"off">​ <input type=​"hidden" name=​"javax.faces.ViewState" id=​"j_id1:​javax.faces.ViewState:​0" value=​"-8409704188153521068:​-2702627544539744037" autocomplete=​"off">​ <input type=​"hidden" name=​"javax.faces.ViewState" id=​"j_id1:​javax.faces.ViewState:​0" value=​"-8409704188153521068:​-2702627544539744037" autocomplete=​"off">​ <input type=​"hidden" name=​"javax.faces.ViewState" id=​"j_id1:​javax.faces.ViewState:​0" value=​"-8409704188153521068:​-2702627544539744037" autocomplete=​"off">​ <input type=​"hidden" name=​"javax.faces.ViewState" id=​"j_id1:​javax.faces.ViewState:​0" value=​"-8409704188153521068:​-2702627544539744037" autocomplete=​"off">​
fileupload.js.xhtml:84 Uploading 50by1000 (5) (2).dta as s31://iqssqa:171898249f9-44731b1e90ac to https://iqssqa.s3.amazonaws.com/10.70122/FK2/CUYUEL/171898249f9-44731b1e90ac?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Date=20200417T185909Z&X-Amz-SignedHeaders=host%3Bx-amz-tagging&X-Amz-Expires=3600&X-Amz-Credential=AKIAIODRE3USX25R5IAA%2F20200417%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Signature=a2a3e43e992b158d5c3e1f0a54700d53bb9cc035a6e4762938b6046c3c72c07c
fileupload.js.xhtml:84 Uploading cheese1 (1) (1) (1) (1).jpg as s31://iqssqa:171898249ed-984b97586944 to https://iqssqa.s3.amazonaws.com/10.70122/FK2/CUYUEL/171898249ed-984b97586944?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Date=20200417T185909Z&X-Amz-SignedHeaders=host%3Bx-amz-tagging&X-Amz-Expires=3600&X-Amz-Credential=AKIAIODRE3USX25R5IAA%2F20200417%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Signature=10c517062eb395bed7e370d6c98274cec74334af6003fdc74c104b8025318f2b
fileupload.js.xhtml:139 S3 Upload complete for cheese1 (1) (1) (1) (1).jpg : s31://iqssqa:171898249ed-984b97586944
fileupload.js.xhtml:139 S3 Upload complete for 50by1000 (5) (2).dta : s31://iqssqa:171898249f9-44731b1e90ac
fileupload.js.xhtml:219 1 : 1 : 2 : 1
fileupload.js.xhtml:219 1 : 2 : 2 : 1
  1. I'm not sure about how many retries there were, will reproduce and watch.
    -Yes, confirmed that when it fails in this mode it tries 20 times. It does not always fail or fail this way though.
  2. as for storage drive/mis configured, this is the same box I've used for multistore testing and the same exact action works when dataset is created first, then added to.

@kcondon
Copy link
Contributor Author

kcondon commented Apr 17, 2020

@qqmyers I've repeated the tests and tried to capture the console and server log output.
I've run the test 3 times, two times failed, one with retry exceeded, one with exception, one time worked. I did not see the storage id problem this time around but this particular scenario seems highly variable at this time. I hope I've given you enough to go on. If you need something more, please let me know.

Jim, please note the three files I'm testing with are tiny.

@qqmyers
Copy link
Member

qqmyers commented Apr 17, 2020

Given the 'Upload complete for ' messages, which indicate a successful upload to S3, and the 20 Retries, it looks like the root cause is that Amazon has just gotten really slow in making the new object available.

(I'm not sure what the exception in the log means for the last trial - is it the view timing out
due to the long processing delays? - There aren't any dataverse classes in the stack trace - anyone have an idea?)

One thing to fix would be to avoid having the dataset fail. Beyond that, we could look at using longer timeouts, but if we're already seeing a view issue, that won't work (and how long should we wait?).

One other test that could be run - other, non us-east-1, regions guarantee you won't get a 404 after creating a new object - using a bucket in one of those regions would show whether there's some other cause here of if it is just Amazon slowing down lately.

@kcondon
Copy link
Contributor Author

kcondon commented Apr 17, 2020

@qqmyers Would it help to make a debug build with lots of extra logging like we did during testing?

@qqmyers
Copy link
Member

qqmyers commented Apr 27, 2020

OK - found a real error as well - a race condition. In create mode, when the UI requests a signed directupload URL, we need to know the path in the bucket which means the dataset (new in create mode) needs a global identifier. I had been checking for a null identifier in the URL request method and setting it then. However, it looks like, with the UI processing files in parallel, it is possible for two calls to get URLs to both see a dataset with a null globalId, resulting in it being set twice with files being sent to two different paths, one of which can't later be found (since the rest of the code assumes the globalId is constant.). I saw this happen on EC2 with a new S3 bucket (where it was easy to see two paths after one 'new dataset' call.

To fix this, I've just switched to assigning the globalId during the DatasetPage init call (if directUpload is enabled) so it is always set before any URL request. That change is now in the PR.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants