Base image processing does not run for backgrounded jobs, possible change to cache! in ProcessAssetMixin?

[astapinski]

Hi there, recently we went through a Carrierwave + carrierwave_backgrounder update:

Before:

carrierwave 1.3.2
carrierwave_backgrounder 0.4.3

After:

carrierwave 3.0.5
carrierwave_backgrounder 1.0.2

Amongst many other things that were an issue, we noticed that base image processing was not working after updating. For example, using an uploader class similar to this:

class AvatarUploader < BaseImageUploader
  include ::CarrierWave::Backgrounder::Delay
  include CarrierWave::MiniMagick
  include ApplicationUploader::StripExif

*** Snip lots of other code ***

  # Process files as they are uploaded:
  process resize_to_limit: [2048, 1024]
  process :auto_rotate_base

  # Create different versions of your uploaded files:
  version :profile do
    process resize_to_limit: [200, 200]
    process :auto_rotate_profile
  end
  version :thumb, from_version: :profile do
    process resize_to_limit: [60, 45]
  end

  private

  def auto_rotate_base
    warn 'AUTO ROTATE BASE'
    manipulate! do |img|
      img.auto_orient
      img = yield(img) if block_given?
      img
    end
  end

  def auto_rotate_profile
    warn 'AUTO ROTATE PROFILE'
    manipulate! do |img|
      img.auto_orient
      img = yield(img) if block_given?
      img
    end
  end

Excuse the different process functions here for auto rotate. In our code they are the same but it helped with debug logging here. There is a StripExif one as well in the included module but it's basically just another process function. BaseImageUploader is just a class that inherits from ApplicationUploader::Base while specifying a content_type_allowlist. When Carrierwave is used by itself without backgrounder or prior to version 3/backgrounder 1.0.2, the base processing of the resize to 2048x1024 and auto_rotate ran fine. After upgrading, these base image processors no longer run.

I think this is a change in recent Carrierwave versions that recreate_versions! does not apply processing to the base image. We've been using a fork for us of carrierwave_backgrounder where we have switched lib/backgrounder/workers/process_asset_mixin.rb to use cache! instead which seems to be both processing the base image as well as versions.

It may be a bit clearer to see with some logging. I enable MiniMagick debug logging with an initializer that has MiniMagick.logger.level = Logger::DEBUG if Rails.env.development? in it. With the current carrierwave_backgrounder 1.0.2, the logs look like this:

web_1  | 15:35:04 sidekiq2.1 | 2024-03-19T19:35:04.902Z pid=103 tid=17wf class=QuieterProcessAssetWorker jid=a89e16f0cf649e2c805374f5 INFO: start
web_1  | 15:35:05 sidekiq2.1 | D, [2024-03-19T15:35:05.539152 #103] DEBUG -- : [0.03s] convert /var/www/tmp/1710876905-328246157739531-0001-7183/profile/e1b53454cde660655264d506564891a2.jpg -auto-orient -resize 200x200> /tmp/image_processing20240319-103-2sjo4a.jpg
web_1  | 15:35:05 sidekiq2.1 | AUTO ROTATE PROFILE
web_1  | 15:35:05 sidekiq2.1 | D, [2024-03-19T15:35:05.556633 #103] DEBUG -- : [0.02s] identify /tmp/mini_magick20240319-103-jwavae.jpg
web_1  | 15:35:05 sidekiq2.1 | D, [2024-03-19T15:35:05.573774 #103] DEBUG -- : [0.02s] mogrify -auto-orient /tmp/mini_magick20240319-103-jwavae.jpg
web_1  | 15:35:05 sidekiq2.1 | D, [2024-03-19T15:35:05.592770 #103] DEBUG -- : [0.02s] identify /var/www/tmp/1710876905-328246157739531-0001-7183/profile/e1b53454cde660655264d506564891a2.jpg
web_1  | 15:35:05 sidekiq2.1 | D, [2024-03-19T15:35:05.615829 #103] DEBUG -- : [0.02s] convert /var/www/tmp/1710876905-328246157739531-0001-7183/thumb/e1b53454cde660655264d506564891a2.jpg -auto-orient -resize 60x45> /tmp/image_processing20240319-103-pcmqq4.jpg
web_1  | 15:35:06 sidekiq2.1 | 2024-03-19T19:35:06.222Z pid=103 tid=17wf class=QuieterProcessAssetWorker jid=a89e16f0cf649e2c805374f5 elapsed=1.32 INFO: done

QuieterProcessAssetWorker by the way is a worker class of ours that inherits from CarrierWave::Workers::ProcessAsset and has some error catching, no real changes beyond that. So in this log, note that "AUTO ROTATE BASE" is not called/shown and the resize to 2048,1024 does not happen.

Here is a log with our fork/branch where the base resizing/auto rotate occurs as it should:

web_1  | 15:24:11 sidekiq2.1 | 2024-03-19T19:24:11.056Z pid=62 tid=17wy class=QuieterProcessAssetWorker jid=145b2c58768b527e08e3b3b4 INFO: start
web_1  | 15:24:12 sidekiq2.1 | D, [2024-03-19T15:24:12.539807 #62] DEBUG -- : [0.04s] identify /tmp/mini_magick20240319-62-upzijg.jpg
web_1  | 15:24:12 sidekiq2.1 | D, [2024-03-19T15:24:12.564045 #62] DEBUG -- : [0.02s] mogrify -auto-orient -strip /tmp/mini_magick20240319-62-upzijg.jpg
web_1  | 15:24:12 sidekiq2.1 | D, [2024-03-19T15:24:12.584408 #62] DEBUG -- : [0.02s] identify /var/www/tmp/1710876252-128886268082131-0001-3691/d7dfab0c2bf1774e50f2510c08ff0f73.jpg
web_1  | 15:24:12 sidekiq2.1 | D, [2024-03-19T15:24:12.636944 #62] DEBUG -- : [0.02s] convert /var/www/tmp/1710876252-128886268082131-0001-3691/d7dfab0c2bf1774e50f2510c08ff0f73.jpg -auto-orient -resize 2048x1024> /tmp/image_processing20240319-62-1qslaq.jpg
web_1  | 15:24:12 sidekiq2.1 | AUTO ROTATE BASE
web_1  | 15:24:12 sidekiq2.1 | D, [2024-03-19T15:24:12.655672 #62] DEBUG -- : [0.02s] identify /tmp/mini_magick20240319-62-su2yco.jpg
web_1  | 15:24:12 sidekiq2.1 | D, [2024-03-19T15:24:12.677259 #62] DEBUG -- : [0.02s] mogrify -auto-orient /tmp/mini_magick20240319-62-su2yco.jpg
web_1  | 15:24:12 sidekiq2.1 | D, [2024-03-19T15:24:12.697086 #62] DEBUG -- : [0.02s] identify /var/www/tmp/1710876252-128886268082131-0001-3691/d7dfab0c2bf1774e50f2510c08ff0f73.jpg
web_1  | 15:24:12 sidekiq2.1 | D, [2024-03-19T15:24:12.723686 #62] DEBUG -- : [0.02s] convert /var/www/tmp/1710876252-128886268082131-0001-3691/profile/d7dfab0c2bf1774e50f2510c08ff0f73.jpg -auto-orient -resize 200x200> /tmp/image_processing20240319-62-i1bh7h.jpg
web_1  | 15:24:12 sidekiq2.1 | AUTO ROTATE PROFILE
web_1  | 15:24:12 sidekiq2.1 | D, [2024-03-19T15:24:12.743014 #62] DEBUG -- : [0.02s] identify /tmp/mini_magick20240319-62-ch9p24.jpg
web_1  | 15:24:12 sidekiq2.1 | D, [2024-03-19T15:24:12.761581 #62] DEBUG -- : [0.02s] mogrify -auto-orient /tmp/mini_magick20240319-62-ch9p24.jpg
web_1  | 15:24:12 sidekiq2.1 | D, [2024-03-19T15:24:12.777593 #62] DEBUG -- : [0.02s] identify /var/www/tmp/1710876252-128886268082131-0001-3691/profile/d7dfab0c2bf1774e50f2510c08ff0f73.jpg
web_1  | 15:24:12 sidekiq2.1 | D, [2024-03-19T15:24:12.796091 #62] DEBUG -- : [0.02s] convert /var/www/tmp/1710876252-128886268082131-0001-3691/thumb/d7dfab0c2bf1774e50f2510c08ff0f73.jpg -auto-orient -resize 60x45> /tmp/image_processing20240319-62-yhhljh.jpg
web_1  | 15:24:13 sidekiq2.1 | 2024-03-19T19:24:13.697Z pid=62 tid=17wy class=QuieterProcessAssetWorker jid=145b2c58768b527e08e3b3b4 elapsed=2.641 INFO: done

Note that "AUTO ROTATE BASE" is in the log and the base image resizing is done as expected.

So at this point I'm asking if anyone else noticed this issue, and if you're open to a PR to have these changes merged in. I should say that we primarily use remote_X_url to start the process here. We don't use direct assignment via assigning a file to the mounted uploader, but I just tested it and it is the same situation/issue/fix as above. When I was debugging carrierwave 3.0.5, the call stack that finally arrived at the image processor functions came through download! and then cache! in carrierwave, so even though it looks a bit odd to me to call cache! to process everything, it was the only way I saw to have both the base image processing done as well as the versions.

Comparison URL
https://github.com/lardawge/carrierwave_backgrounder/compare/master...HiMamaInc:carrierwave_backgrounder:fix/process_asset?expand=1

Let me know what you think and if you think this would be appropriate for a PR. Thanks!