When running feature Rspecs, I receive the following error (full trace at the bottom of this message)
Puma output
Rack app error handling request { GET /rails/active_storage/disk/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDRG9JYTJWNVNTSm5kbUZ5YVdGdWRITXZSM0IxTkRGRFRWQlFaVXRNYVUxaVpuQjZXVmw1UTNBMUx6RXhNR1V3TVRka01UWTVNalZrWXpkak5UQTNNamhqT1dNeE5UUmhOREl3TURjNVlXRTJaVFZtWTJNME16VmtZak5sTm1VNU4ySXhNemd3WldObFl6Z0dPZ1pGVkRvUVpHbHpjRzl6YVhScGIyNUpJajFwYm14cGJtVTdJR1pwYkdWdVlXMWxQU0pwYldGblpTNXdibWNpT3lCbWFXeGxibUZ0WlNvOVZWUkdMVGduSjJsdFlXZGxMbkJ1WndZN0JsUTZFV052Ym5SbGJuUmZkSGx3WlVraURtbHRZV2RsTDNCdVp3WTdCbFE9IiwiZXhwIjoiMjAxOS0wMS0yNVQxMToxNjoyOS40NDBaIiwicHVyIjoiYmxvYl9rZXkifX0=--db9451afdc95b292aa6a77c40e00ab0ceb687766/image.png }
#<Errno::ENOENT: No such file or directory @ rb_file_s_mtime - /path/to/rails/app/tmp/storage/va/ri/variants/Gpu41CMPPeKLiMbfpzYYyCp5/110e017d16925dc7c50728c9c154a420079aa6e5fcc435db3e6e97b1380ecec8>
(followed by the full trace at the end of this message)
Rspec outpout
Failure/Error: last_modified = ::File.mtime(path).httpdate
Errno::ENOENT:
No such file or directory @ rb_file_s_mtime - /path/to/rails/app/tmp/storage/va/ri/variants/Gpu41CMPPeKLiMbfpzYYyCp5/110e017d16925dc7c50728c9c154a420079aa6e5fcc435db3e6e97b1380ecec8
(followed by the full trace at the end of this message)
Context
product.image
is an ActiveStorage attachment. During the test the "products/_form" partial is rendered and is displaying the attachment file (namely a png image) with the following code: = image_tag url_for(product.image.variant(resize: "120x120"))
. If I comment out this line, the error does not occur anymore.
The test itself succeed every times, the error seems to be triggered after the test. I verified all my after
blocks, it seems to happen after all my after blocks.
The trace indicates that ActiveStorage::DiskController.serve_file
triggers the errors. Is it that ActiveStorage app is not shutting down gracefully ?
I'm using active_storage.service = :test
configuration, but :file
gives the same errors.
Image broken
While a test fail, I can see in the "remote controlled" browser that the image is not display and there is a broken image icon instead.
Running the tests
There is a group of 4 featured tests that are going through the render of the "products/_form" partial. When I run the 4 tests in a random order the error occurs randomly. Sometime I can see the error 2 times, sometimes 3 times.
when I run the tests individually the error does never appear.
How I attach the image
This is the helper I use to attach the file to the model before going through the test :
path = Rails.root.join 'spec', 'support', 'fixtures', 'img1.png'
raise 'Image does not exist' unless File.exist? path
product.image.attach io: File.open(path), filename: 'image.png'
I also tried to use this helper :
path = Rails.root.join 'spec', 'support', 'fixtures', 'img1.png'
raise 'Image does not exist' unless File.exist? path
blob = ActiveStorage::Blob.create_after_upload! io: path.open, \
filename: 'img1.png', content_type: 'image/png'
product.images.attach blob
And this helper :
path = Rails.root.join 'spec', 'support', 'fixtures', 'img1.png'
raise 'Image does not exist' unless File.exist? path
byte_size = path.size
checksum = Digest::MD5.file(path).base64digest
blob = ActiveStorage::Blob.create_before_direct_upload!(filename: 'img1.png', \
byte_size: byte_size, checksum: checksum, content_type: 'image/png').tap do |blob|
ActiveStorage::Blob.service.upload(blob.key, path.open)
end
product.images.attach blob
System configuration
Rails version: 5.2.2
Ruby version: ruby 2.5.3p105 (2018-10-18 revision 65156) [x86_64-linux]
Rbenv version: rbenv 1.1.1-39-g59785f6
Rspec related versions: rspec 3.8.0 - capybara 3.12.0 - selenium-webdriver 3.141.0
Full trace
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/rack-2.0.6/lib/rack/file.rb:63:in `mtime'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/rack-2.0.6/lib/rack/file.rb:63:in `serving'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activestorage-5.2.2/app/controllers/active_storage/disk_controller.rb:42:in `serve_file'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activestorage-5.2.2/app/controllers/active_storage/disk_controller.rb:12:in `show'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/abstract_controller/base.rb:194:in `process_action'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_controller/metal/rendering.rb:30:in `process_action'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/callbacks.rb:132:in `run_callbacks'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/abstract_controller/callbacks.rb:41:in `process_action'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_controller/metal/rescue.rb:22:in `process_action'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications.rb:168:in `block in instrument'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications.rb:168:in `instrument'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/abstract_controller/base.rb:134:in `process'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionview-5.2.2/lib/action_view/rendering.rb:32:in `process'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_controller/metal.rb:191:in `dispatch'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_controller/metal.rb:252:in `dispatch'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/routing/route_set.rb:34:in `serve'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/journey/router.rb:52:in `block in serve'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/journey/router.rb:35:in `each'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/journey/router.rb:35:in `serve'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/routing/route_set.rb:840:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/rack-2.0.6/lib/rack/tempfile_reaper.rb:15:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/rack-2.0.6/lib/rack/etag.rb:25:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/rack-2.0.6/lib/rack/conditional_get.rb:25:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/rack-2.0.6/lib/rack/head.rb:12:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:232:in `context'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:226:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/middleware/cookies.rb:670:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/callbacks.rb:98:in `run_callbacks'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/railties-5.2.2/lib/rails/rack/logger.rb:38:in `call_app'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/railties-5.2.2/lib/rails/rack/logger.rb:26:in `block in call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/tagged_logging.rb:71:in `block in tagged'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/tagged_logging.rb:28:in `tagged'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/tagged_logging.rb:71:in `tagged'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/railties-5.2.2/lib/rails/rack/logger.rb:26:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/middleware/request_id.rb:27:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/rack-2.0.6/lib/rack/method_override.rb:22:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/rack-2.0.6/lib/rack/runtime.rb:22:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/middleware/executor.rb:14:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/actionpack-5.2.2/lib/action_dispatch/middleware/static.rb:127:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/rack-2.0.6/lib/rack/sendfile.rb:111:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/railties-5.2.2/lib/rails/engine.rb:524:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:68:in `block in call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:53:in `each'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:53:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/capybara-3.12.0/lib/capybara/server/middleware.rb:48:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/configuration.rb:225:in `call'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/server.rb:658:in `handle_request'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/server.rb:472:in `process_client'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/server.rb:332:in `block in run'
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/thread_pool.rb:133:in `block in spawn_thread'
#
# Showing full backtrace because every line was filtered out.
# See docs for RSpec::Configuration#backtrace_exclusion_patterns and
# RSpec::Configuration#backtrace_inclusion_patterns for more information.
# ------------------
# --- Caused by: ---
# Capybara::CapybaraError:
# Your application server raised an error - It has been raised in your test code because Capybara.raise_server_errors == true
# /opt/rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/capybara-3.12.0/lib/capybara/session.rb:147:in `raise_server_error!'
Update
(Sorry for being silent, I had an emergency to attend to)
Here is an interesting information. I inserted after this line, this code: puts "SERVING #{path} - Exist ? #{File.exist? path}"
And here is the output (observe the files names and the boolean value at the end of each line):
SERVING /tmp/active_storage_tests20190129-10797-1rebdf7/Me/GK/MeGKkqgbb7Sg4RbPoCYWR6pZ - Exist ? true
SERVING /tmp/active_storage_tests20190129-10797-1rebdf7/sG/3v/sG3vd2viGWmaf69pNXSChZPa - Exist ? true
SERVING /tmp/active_storage_tests20190129-10797-1rebdf7/fy/2C/fy2C8PpaR96YgCzwt5WVBLrQ - Exist ? true
SERVING /tmp/active_storage_tests20190129-10797-1rebdf7/sG/3v/sG3vd2viGWmaf69pNXSChZPa - Exist ? true
. (green dot)
SERVING /tmp/active_storage_tests20190129-10797-1rebdf7/Me/GK/MeGKkqgbb7Sg4RbPoCYWR6pZ - Exist ? false
SERVING /tmp/active_storage_tests20190129-10797-1rebdf7/sG/3v/sG3vd2viGWmaf69pNXSChZPa - Exist ? false
SERVING /tmp/active_storage_tests20190129-10797-1rebdf7/Me/GK/MeGKkqgbb7Sg4RbPoCYWR6pZ - Exist ? false
SERVING /tmp/active_storage_tests20190129-10797-1rebdf7/fy/2C/fy2C8PpaR96YgCzwt5WVBLrQ - Exist ? false
F (red F)
SERVING /tmp/active_storage_tests20190129-10797-1rebdf7/Me/GK/MeGKkqgbb7Sg4RbPoCYWR6pZ - Exist ? false
SERVING /tmp/active_storage_tests20190129-10797-1rebdf7/sG/3v/sG3vd2viGWmaf69pNXSChZPa - Exist ? false
SERVING /tmp/active_storage_tests20190129-10797-1rebdf7/Me/GK/MeGKkqgbb7Sg4RbPoCYWR6pZ - Exist ? false
SERVING /tmp/active_storage_tests20190129-10797-1rebdf7/fy/2C/fy2C8PpaR96YgCzwt5WVBLrQ - Exist ? false
F (red F)
SERVING /tmp/active_storage_tests20190129-10797-1rebdf7/Tx/DL/TxDLPEk3ykf8ETkURY5YZPgY - Exist ? true
As we can see the files path are the same, even between tests. Tough the database is cleaned between each tests. So there is "somewhere" where the file checksum is kept, for activestorage to reuse the same blob record. As a result it reuse the same file path and that's the reason why I have a FileNotFound error.
Any idea ? Please note that, additionally to DatabaseCleaner, I have an after block defined like this :
config.after(:each) do
ActiveStorage::Current.reset
ActiveStorage::Attachment.all.each(&:delete)
ActiveStorage::Blob.all.each(&:delete)
end
I suspect a bug
Filled a PR with an application to reproduce https://github.com/rails/rails/issues/34989
Waiting for them response
File.exist? ActiveStorage::Blob.service.path_for(image.blob.key)
– Lydialydian