ruby on rails - Errno::ENOENT: No such file or directory @ rb_file_s_mtime after feature tests

Question

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

Answer 1

The fact that the test passes just means that the test does not depend on that image being found. A broken image link will not generally cause a test to fail and it is in fact often the case that test writers do not even bother to supply mock images because it is (perceived to be) too much work and not relevant to the thing being tested.

See folks, this is why we ask for an example. Now that the OP has posted an example, we can see that his problem is browser caching, and will be solved by replacing

product.images.attach io: File.open(path), filename: 'image.png'

with

product.images.attach io: File.open(path), filename: "image-#{Time.now.strftime("%s%L")}.png"

in the helper that does the attachment. I would not have solved this without having the example.

Explanation

ActiveStorage handles saving and serving files. OP was saving and serving images with it, which is definitely what it was intended for. In order to allow for different services to serve files in different ways, ActiveStorage separates the published URL from the actual image serving URL.

The published URL is almost a permalink: it is an encoded version of the database key for the attachment. ActiveStorage processes a request for the URL by looking up where the file is stored and sending a 302 temporary redirect to the URL that can be used to access the file, called a "service URL". When using AWS S3 to store files, the service URL can be a signed URL that expires quickly but nevertheless connects the browser directly to S3 rather than having to go through the web server as intermediary.

By default, the service URL is good for 5 minutes, and ActiveRecord explicitly sets

Cache-Control: max-age=300, private

on the 302 redirect. The browser caches this redirect response and for the next 5 minutes the browser will not even attempt to use or verify the published URL, it will immediately replace the public URL with the cached service URL.

Unfortunately, while the public URL is predictably recreated, the service URL is randomly generated, so when the browser does its automatic redirection, the previously valid service URL no longer works. The solution (or workaround, depending on your point of view) is to distinguish the public URLs by including a timestamp in the filename, so that tests will not reuse public URLs.

Sidenote

By the way, you should not be using url_for with image_tag. Change your ERB from

= image_tag url_for(product.image.variant(resize: "120x120"))

to

= image_tag(product.image.variant(resize: "120x120"))

Rails is smart enough to handle either case, but the latter way is the recommended way.