Closed eporter23 closed 5 years ago
@eporter23 Can we sit down together to try this? I'd like to pull the error as it happens.
Stacktrace:
F, [2019-06-19T21:19:25.538212 #21532] FATAL -- : [bad0a1b1-651d-44d4-b0ba-deddf39524c5]
F, [2019-06-19T21:19:25.538248 #21532] FATAL -- : [bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/share/ruby/fileutils.rb:1293:in `copy_stream'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/share/ruby/fileutils.rb:1293:in `block (2 levels) in copy_file'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/share/ruby/fileutils.rb:1292:in `open'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/share/ruby/fileutils.rb:1292:in `block in copy_file'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/share/ruby/fileutils.rb:1291:in `open'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/share/ruby/fileutils.rb:1291:in `copy_file'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/share/ruby/fileutils.rb:432:in `copy_file'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/share/ruby/fileutils.rb:359:in `block in cp'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/share/ruby/fileutils.rb:1463:in `block in fu_each_src_dest'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/share/ruby/fileutils.rb:1479:in `fu_each_src_dest0'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/share/ruby/fileutils.rb:1461:in `fu_each_src_dest'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/share/ruby/fileutils.rb:358:in `cp'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] carrierwave (1.3.1) lib/carrierwave/sanitized_file.rb:235:in `copy!'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] carrierwave (1.3.1) lib/carrierwave/sanitized_file.rb:225:in `copy_to'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] carrierwave (1.3.1) lib/carrierwave/uploader/cache.rb:134:in `cache!'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] carrierwave (1.3.1) lib/carrierwave/mounter.rb:44:in `block in cache'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] carrierwave (1.3.1) lib/carrierwave/mounter.rb:42:in `map'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] carrierwave (1.3.1) lib/carrierwave/mounter.rb:42:in `cache'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] carrierwave (1.3.1) lib/carrierwave/mount.rb:146:in `file='
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] carrierwave (1.3.1) lib/carrierwave/orm/activerecord.rb:70:in `file='
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activemodel (5.1.7) lib/active_model/attribute_assignment.rb:46:in `public_send'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activemodel (5.1.7) lib/active_model/attribute_assignment.rb:46:in `_assign_attribute'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activemodel (5.1.7) lib/active_model/attribute_assignment.rb:40:in `block in _assign_attributes'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activemodel (5.1.7) lib/active_model/attribute_assignment.rb:39:in `each'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activemodel (5.1.7) lib/active_model/attribute_assignment.rb:39:in `_assign_attributes'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activerecord (5.1.7) lib/active_record/attribute_assignment.rb:26:in `_assign_attributes'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activemodel (5.1.7) lib/active_model/attribute_assignment.rb:33:in `assign_attributes'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activerecord (5.1.7) lib/active_record/attribute_assignment.rb:10:in `attributes='
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] hyrax (3.0.0.pre.beta1) app/controllers/hyrax/uploads_controller.rb:6:in `create'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/abstract_controller/base.rb:186:in `process_action'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_controller/metal/rendering.rb:30:in `process_action'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/abstract_controller/callbacks.rb:20:in `block in process_action'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activesupport (5.1.7) lib/active_support/callbacks.rb:131:in `run_callbacks'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/abstract_controller/callbacks.rb:19:in `process_action'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_controller/metal/rescue.rb:20:in `process_action'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activesupport (5.1.7) lib/active_support/notifications.rb:166:in `block in instrument'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activesupport (5.1.7) lib/active_support/notifications/instrumenter.rb:21:in `instrument'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activesupport (5.1.7) lib/active_support/notifications.rb:166:in `instrument'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_controller/metal/instrumentation.rb:30:in `process_action'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_controller/metal/params_wrapper.rb:252:in `process_action'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activerecord (5.1.7) lib/active_record/railties/controller_runtime.rb:22:in `process_action'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/abstract_controller/base.rb:124:in `process'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionview (5.1.7) lib/action_view/rendering.rb:30:in `process'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_controller/metal.rb:189:in `dispatch'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_controller/metal.rb:253:in `dispatch'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/routing/route_set.rb:31:in `serve'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/journey/router.rb:50:in `block in serve'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/journey/router.rb:33:in `each'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/journey/router.rb:33:in `serve'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/routing/route_set.rb:844:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] railties (5.1.7) lib/rails/engine.rb:522:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] railties (5.1.7) lib/rails/railtie.rb:185:in `public_send'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] railties (5.1.7) lib/rails/railtie.rb:185:in `method_missing'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/routing/mapper.rb:17:in `block in <class:Constraints>'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/routing/mapper.rb:46:in `serve'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/journey/router.rb:50:in `block in serve'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/journey/router.rb:33:in `each'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/journey/router.rb:33:in `serve'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/routing/route_set.rb:844:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] omniauth (1.9.0) lib/omniauth/strategy.rb:192:in `call!'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] omniauth (1.9.0) lib/omniauth/strategy.rb:169:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] warden (1.2.8) lib/warden/manager.rb:36:in `block in call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] warden (1.2.8) lib/warden/manager.rb:34:in `catch'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] warden (1.2.8) lib/warden/manager.rb:34:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] rack (2.0.7) lib/rack/etag.rb:25:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] rack (2.0.7) lib/rack/conditional_get.rb:38:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] rack (2.0.7) lib/rack/head.rb:12:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] rack (2.0.7) lib/rack/session/abstract/id.rb:232:in `context'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] rack (2.0.7) lib/rack/session/abstract/id.rb:226:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/middleware/cookies.rb:613:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] active-fedora (11.5.4) lib/active_fedora/ldp_cache.rb:26:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] flipflop (2.6.0) lib/flipflop/feature_cache.rb:12:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/middleware/callbacks.rb:26:in `block in call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activesupport (5.1.7) lib/active_support/callbacks.rb:97:in `run_callbacks'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/middleware/callbacks.rb:24:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/middleware/debug_exceptions.rb:59:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] railties (5.1.7) lib/rails/rack/logger.rb:36:in `call_app'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] railties (5.1.7) lib/rails/rack/logger.rb:24:in `block in call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activesupport (5.1.7) lib/active_support/tagged_logging.rb:69:in `block in tagged'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activesupport (5.1.7) lib/active_support/tagged_logging.rb:26:in `tagged'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activesupport (5.1.7) lib/active_support/tagged_logging.rb:69:in `tagged'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] railties (5.1.7) lib/rails/rack/logger.rb:24:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/middleware/request_id.rb:25:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] rack (2.0.7) lib/rack/method_override.rb:22:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] rack (2.0.7) lib/rack/runtime.rb:22:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] activesupport (5.1.7) lib/active_support/cache/strategy/local_cache_middleware.rb:27:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] actionpack (5.1.7) lib/action_dispatch/middleware/executor.rb:12:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] rack (2.0.7) lib/rack/sendfile.rb:111:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] railties (5.1.7) lib/rails/engine.rb:522:in `call'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/rack/thread_handler_extension.rb:97:in `process_request'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:157:in `accept_and_process_next_request'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:110:in `main_loop'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/request_handler.rb:415:in `block (3 levels) in start_threads'
[bad0a1b1-651d-44d4-b0ba-deddf39524c5] /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'
@SolomonHD @mprefer Looks like the filesystem isn't big enough for a 2.15 GB file to fit?
@mprefer can you place an estimation of the work you have for this issue?
Added additional space to the root file system, increasing it to 50G.
Edited '/etc/systemd/system/multi-user.target.wants/httpd.service', set PrivateTmp=false so that systemd does not create randomly named folders in /tmp where the file uploads were going. Now they will land in /tmp and make clean cron jobs easier.
Files up to a certain size will upload without error. However, there is a Javascript program that validates the size of the file before an upload attempt.
@rotated8 @mprefer I tried a large file upload again through the UI but got an error. I tested using the FileSet uploader with a large (3GB) and very small file. More details are logged here.
For the 3GB file, the status indicated it completed (after ~30 min on my home connection) around 12:47 pm 7/19/19 but the Hyrax Add Files checkbox stayed red. I was not able to save the new work I was trying to create and as far as I can tell, it's not in fedora-cor-test.
I will test again with a 2GB file (was our form max file size set to 2.5?)
Retested again using the Curate prod UI and a 2GB file. This seemed to stall out once the visual status bar completed - the "Files uploaded" message does not display, and the Add files icon in the sidebar does not turn green. Added these notes to the linked document above.
@mprefer @rotated8 I tested a 2.15 GB file again in Curate prod, with the same results. I wait for the large file upload - status bar shows it's completed, but there is no confirmation status message and the Add Files icon in the sidebar of the form does not turn green.
Discovered an HTTP 502 error in the Apache logs after uploading a 2+ Gig file. HTTP 502 errors are broadly defined, but usually associated with the "Bad Gateway" error, which usually indicates there is a timeout somewhere in flow from source to destination and all points between.
After much research and trial & error, implemented the following 2 solutions that seem to have rectified the problem:
In the ELB settings for the balancer that both curate and curate-test use, I increased the "Idle Timeout" value from the default of 60 seconds to 3600 seconds (1 hour):
Also added "PassengerStickySessions On" to /etc/httpd/conf.d/passenger.conf on each Apache instance.
Since making these changes in both curate & curate-test, have upload multiple files to each with success. Mostly OS ISO files and 2 MP4 files ranging >=2Gig and <2.5Gig. All these tests thus far have succeeded. Note to anyone testing, there is a slight lag between when the status bar has reached the maximum and the message "Files Uploaded" appear in the UI above the status bar.
I uploaded a 1.4GB uncompressed yearbook PDF: https://curate-test.library.emory.edu/concern/parent/631cjsxkt6-cor/file_sets/9182jm63zm-cor The upload appeared to complete, but I am unable to download the file from Curate: I also can't find it in Fedora. I'm not sure if the various ingest jobs are still running, because I don't see checksums and other info populated yet, so I will check back on it later.
Found many of these in the Sidekiq log. Hope it helps.
{ "context": "Job raised exception", "job": { "class": "ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper", "wrapped": "IngestJob", "queue": "default", "args": [ { "job_class": "IngestJob", "job_id": "eb782b27-e012-4406-b0a1-c468bc3e2659", "provider_job_id": null, "queue_name": "default", "priority": null, "arguments": [ { "_aj_globalid": "gid://dlp-curate/JobIoWrapper/790" } ], "executions": 0, "locale": "en" } ], "retry": true, "jid": "40dfe2a01b6c2dbeb51ca54f", "created_at": 1569867568.3141167, "enqueued_at": 1570114051.2614255, "error_message": "STATUS: 500 org.modeshape.jcr.value.binary.BinaryStoreException: org.modeshape.jcr.value.binary.BinaryStoreException: Unable to find binary value with key \"da39a3ee5e6b4b0d3255bfef95601890afd80709\" within binary store at \"/tmp/modeshape-binary-store\"\n\tat org.modeshape.jcr.value.binary.S3BinaryStore.storeValue(S3BinaryStore.java:231)\n\tat org.modeshape.jcr.value.binary.AbstractBinaryStore.storeValue(AbstractBinaryStore.java:251)\n\tat org.modeshape.jcr.value.binary.BinaryStoreValueFactory.create(BinaryStoreValueFactory.java:257)\n\tat org.modeshape.jcr.value.binary.BinaryStoreValueFactory.create(BinaryStoreValueFactory.java:49)\n\tat org.modeshape.jcr.JcrValueFactory.createBinary(JcrValueFactory.java:149)\n\tat org.modeshape.jcr.JcrValueFactory.createBinary(JcrValueFactory.java:41)\n\tat org.fcrepo.kernel.modeshape.FedoraBinaryImpl.setContent(FedoraBinaryImpl.java:179)\n\tat org.fcrepo.http.api.ContentExposingResource.replaceResourceBinaryWithStream(ContentExposingResource.java:623)\n\tat org.fcrepo.http.api.Fedo...", "error_class": "Ldp::HttpError", "failed_at": 1569867569.642823, "retry_count": 16, "retried_at": 1570048072.5132258 }, "jobstr": "{\"class\":\"ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper\",\"wrapped\":\"IngestJob\",\"queue\":\"default\",\"args\":[{\"job_class\":\"IngestJob\",\"job_id\":\"eb782b27-e012-4406-b0a1-c468bc3e2659\",\"provider_job_id\":null,\"queue_name\":\"default\",\"priority\":null,\"arguments\":[{\"_aj_globalid\":\"gid://dlp-curate/JobIoWrapper/790\"}],\"executions\":0,\"locale\":\"en\"}],\"retry\":true,\"jid\":\"40dfe2a01b6c2dbeb51ca54f\",\"created_at\":1569867568.3141167,\"enqueued_at\":1570114051.2614255,\"error_message\":\"STATUS: 500 org.modeshape.jcr.value.binary.BinaryStoreException: org.modeshape.jcr.value.binary.BinaryStoreException: Unable to find binary value with key \\"da39a3ee5e6b4b0d3255bfef95601890afd80709\\" within binary store at \\"/tmp/modeshape-binary-store\\"\n\tat org.modeshape.jcr.value.binary.S3BinaryStore.storeValue(S3BinaryStore.java:231)\n\tat org.modeshape.jcr.value.binary.AbstractBinaryStore.storeValue(AbstractBinaryStore.java:251)\n\tat org.modeshape.jcr.value.binary.BinaryStoreValueFactory.create(BinaryStoreValueFactory.java:257)\n\tat org.modeshape.jcr.value.binary.BinaryStoreValueFactory.create(BinaryStoreValueFactory.java:49)\n\tat org.modeshape.jcr.JcrValueFactory.createBinary(JcrValueFactory.java:149)\n\tat org.modeshape.jcr.JcrValueFactory.createBinary(JcrValueFactory.java:41)\n\tat org.fcrepo.kernel.modeshape.FedoraBinaryImpl.setContent(FedoraBinaryImpl.java:179)\n\tat org.fcrepo.http.api.ContentExposingResource.replaceResourceBinaryWithStream(ContentExposingResource.java:623)\n\tat org.fcrepo.http.api.Fedo...\",\"error_class\":\"Ldp::HttpError\",\"failed_at\":1569867569.642823,\"retry_count\":16,\"retried_at\":1570048072.5132258}" }
Relates to epic #25. Tested uploading a 2GB file to a new work. File upload completed, but I received an Internal Server Error result.