Errors are silently swallowed instead of being raised to the background processor
Opened this issue · 1 comments
I have been working on debugging strange behavior in our company's product. We are using paperclip 4.2 and delayed_paperclip 3.0.0 with sidekiq pro 3.3.2 / sidekiq 4.1.4 as the background processor and Amazon S3 as the backing storage service. We could see that the DelayedPaperclip::ProcessJob worker was running, and completing successfully, but our converted files were never saved to the S3 bucket. After much confusion I decided to try running a copy of the worker synchronously at the rails console instead of in the background, and finally discovered the reason why:
irb(main):014:0> DelayedPaperclip::ProcessJob.new.perform( 'Image', 10, 'image' )
Image Load (0.5ms) SELECT "images".* FROM "images" WHERE "images"."id" = $1 ORDER BY "images"."id" ASC LIMIT 1 [["id", 10]]
[paperclip] copying feature-refi/0615485b39f4d0ffcc1a6a4e7f51f32f6d461596 to local file /tmp/bed59859200fbddaa20005ec96dd142620160912-20766-1a3kgr4
Command :: identify -format '%wx%h,%[exif:orientation]' '/tmp/bed59859200fbddaa20005ec96dd142620160912-20766-1a3kgr4[0]' 2>/dev/null
[paperclip] An error was received while processing: #<Paperclip::Errors::CommandNotFoundError: Could not run the `identify` command. Please install ImageMagick.>
Command :: identify -format '%wx%h,%[exif:orientation]' '/tmp/bed59859200fbddaa20005ec96dd142620160912-20766-1a3kgr4[0]' 2>/dev/null
[paperclip] An error was received while processing: #<Paperclip::Errors::CommandNotFoundError: Could not run the `identify` command. Please install ImageMagick.>
Command :: identify -format '%wx%h,%[exif:orientation]' '/tmp/bed59859200fbddaa20005ec96dd142620160912-20766-1a3kgr4[0]' 2>/dev/null
[paperclip] An error was received while processing: #<Paperclip::Errors::CommandNotFoundError: Could not run the `identify` command. Please install ImageMagick.>
Command :: identify -format '%wx%h,%[exif:orientation]' '/tmp/bed59859200fbddaa20005ec96dd142620160912-20766-1a3kgr4[0]' 2>/dev/null
[paperclip] An error was received while processing: #<Paperclip::Errors::CommandNotFoundError: Could not run the `identify` command. Please install ImageMagick.>
[paperclip] saving feature-refi/0615485b39f4d0ffcc1a6a4e7f51f32f6d461596
(0.2ms) BEGIN
(0.2ms) ROLLBACK
=> nil
irb(main):015:0>
From these lines I could see that the issue was with the installation of ImageMagick and that Paperclip was not able to find the binaries. That makes sense, and is not an issue for this repo / team. What is an issue for this repo / team is that those errors were silently swallowed by the DelayedPaperclip::ProcessJob worker instead of being re-raised so that they could be handled by the background processor's retry mechanism. This prevented the actual issue from appearing as a failure in our background job tracking, and prevented it from being reported to error-tracking systems like Airbrake and Honeybadger, thus creating the illusion that the worker was running successfully when it in fact was not.
In other words, here's the issue:
Steps To Reproduce: Set up an environment in a way that Paperclip will encounter an error when it tries to convert a file (for example, break the installation of ImageMagick), then run a DelayedPaperclip::ProcessJob worker in the background.
Observed Behavior: The worker creates a log line indicating that an error was raised, but does not raise the error any further. The background processor sees that job as successfully completed and does not queue the job for retrying. Any error-reporting libraries like Honeybadger or Airbrake are never informed of the error.
Expected Behavior: The worker should create the log line as it currently does, but then should also re-raise the error. The background processor should see that job as having failed, and could choose to queue it for retrying (depending on configuration). Any error-reporting libraries like Honeybadger or Airbrake should receive and report the error as normal.
If I have time later I may submit a PR for this, but I thought I would at least submit an issue first so that it can be on the team's radar.
Additional notes added via edit:
I should note that :whiny is turned on in our Paperclip.options hash:
irb(main):001:0> ap Paperclip.options
{
:whiny => true,
:image_magick_path => nil,
:command_path => nil,
:log => true,
:log_command => true,
:swallow_stderr => true,
:content_type_mappings => {},
:use_exif_orientation => true,
:logger => #<ActiveSupport::Logger:0x007f7a637a5e10 ... >
}
=> nil
... which, according to the Paperclip documentation, means that Paperclip should be raising errors when it cannot process an image. (The :swallow_stderr option setting, despite its name, has nothing to do with the raising or rescuing of errors by Paperclip -- that option gets passed straight through to the Cocaine gem, where it affects the way that Cocaine interacts with STDERR when running a shell command.) Thus why I believe the issue is with DelayedPaperclip silencing that error.
That's a pretty old version of Paperclip which is vulnerable to a DoS attack. I'm not seeing this with Paperclip 5.1.0, DelayedPaperclip 3.0.1 and Que 0.12 when raising from my custom processor, it retries the job just fine.
I don't see a rescue in the DelayedPaperclip code either so you might want to try upgrading to the latest version of Paperclip.