RMagick, Paperclip, S3 Silent Failing

[jeffblake]

I've got an Rmagick script that basically generates an image and saves it to paperclip. It was working fine with Resque.

Setup: Heroku, Unicorn

I can actually sometimes get it process locally if I manually add the job via console. But it always fails on Heroku whether it was added via console or not.

When it fails, it does not add it to the retry queue.

here is what my script looks like:

  def make_ticket_qr
qr_plus_logo = Magick::Image.read(self.qr_with_logo.url).first

tmp_img = Tempfile.new(['qr', '.png'])
#tmp_img = Tempfile.new("#{Rails.root}/tmp/myfile_#{Process.pid}.png")

i = Magick::Image.read('https://s3.amazonaws.com/media.goodnightsapp.com/ticket-bg2.png').first
text = Magick::Draw.new
text.font_family = "Helvetica-Neue-Bold"
text.font_style = Magick::NormalStyle
text.font_weight = Magick::BoldWeight
text.stroke = "none"
text.annotate(i, 800, 50, 360, 15, event.title) do
  self.gravity = Magick::NorthWestGravity
  self.pointsize = 36
  self.fill = "black"
  self.undercolor = "red"
end
text.annotate(i, 800, 50, 360, 17, event.title) do
  self.gravity = Magick::NorthWestGravity
  self.pointsize = 36
  self.fill = "white"
  self.undercolor = "transparent"
end
text.annotate(i, 0, 0, 360, 60, event.venue.username) do
  self.gravity = Magick::NorthWestGravity
  self.pointsize = 30
  self.fill = "white"
  self.undercolor = 'transparent'
end
text.gravity = Magick::SouthEastGravity
text.annotate(i, 0, 0, 15, 150, event.nice_date) do
  self.pointsize = 30
  self.fill = "white"
  self.undercolor = 'transparent'
end
price, size = nice_price(event)
text.annotate(i, 0, 0, 17, 17, price) do
  self.pointsize = size
  self.fill = "black"
  self.undercolor = "red"
end
text.annotate(i, 0, 0, 15, 15, price) do
  self.pointsize = size
  self.fill = "white"
  self.undercolor = 'transparent'
end
i = i.composite(qr_plus_logo, 15, 15, Magick::OverCompositeOp)
i.format = 'png'

File.open(tmp_img.path, 'w:ASCII-8BIT') do |f|
    f.write i.to_blob
end
self.ticket_qr = tmp_img
self.save!
tmp_img.close
tmp_img.unlink
qr_plus_logo.destroy!
i.destroy!

end

[ezkl]

Until recently, Paperclip was wholly incompatible w/ sidekiq due to one of its dependency not being thread-safe. See this issue, Sidekiq #310, and the Problems and Troubleshooting section of the wiki for more details.

[mperham]

No log output or exceptions? Are you using sidekiq 2.1.1?

[jeffblake]

Yes, I just upgraded. From the worker log I have:

2012-08-07T23:58:46+00:00 app[worker.1]: 2012-08-07T23:58:46Z 2 TID-1gmr4k DEBUG: enqueued schedule: {"retry":true,"queue":"default","backtrace":true,"class":"QrGeneratorWorker","args":[450],"at":1344383921.8842878}
2012-08-07T23:58:46+00:00 app[worker.1]: 2012-08-07T23:58:46Z 2 TID-1bgv7o QrGeneratorWorker MSG-1kb4e0 INFO: start
2012-08-07T23:58:46+00:00 app[worker.1]: EventPromoter Load (1.9ms) SELECT "event_promoters".* FROM "event_promoters" WHERE "event_promoters"."id" = $1 LIMIT 1 [["id", 450]]

Then nothing else.

[jeffblake]

Additonally, I thought it may have been due to the transaction not completing before the job is ran, so I have added both after_commit on: :create as well as delaying the job by 5 seconds to no success.

[mperham]

Looks like postgres. I'm starting to wonder about the postgres driver. You using the pg gem?

[jeffblake]

Yes, both locally and heroku

[jeffblake]

I just tried wrapping it in a Mutex with no success either

[mperham]

I would try rescuing Exception in your perform and see if that catches something. Sidekiq only catches StandardErrors by default. It's possible the system is throwing some arcane error that is causing it to simply die.

[mperham]

What does PG.threadsafe? return?

[jeffblake]

PG.threadsafe? = true

I caught the exception: "stack level too deep"
While running this line:

qr = Magick::Image.read(self.big_qr).first

Googling around led me to believe this is a RMagick configuration issue... but if the only variable in my setup that I'm changing is using Sidekiq, that leads me to believe otherwise? Is there anything in sidekiq that could cause this?

[jeffblake]

In my gemfile:

gem 'rmagick', require: false

In the Model class the method is called from:

require 'RMagick'
class EventPromoter < ActiveRecord::Base

edit: just tried removing the require, still the same error.

[jc00ke]

Have you tried replacing RMagick with MiniMagick? I've always had good luck
with MM & I believe it avoids some of the memory issues RMagick can have.
http://github.com/probablycorey/mini_magick

[jeffblake]

Interesting suggestion... I tried it out, and it works beautifully. Thanks for the tip - reduced memory footprint and slug size

[mperham]

Ok, I'm going to put RMagick on our "troublesome gems" list.

[jc00ke]

@mperham can you put RMagick on the "troublesome gems" list 😉