Shrine

Encoding::UndefinedConversionError on promotion

Bug
#1

Hi - I am having a very strange issue relating to image promotion. With certain images, so far only jpegs from iPhones, I get an Encoding::UndefinedConversionError error when I try to promote the image. I am not sure if this is happening because of something in Shrine (3.1.0) or something in image_processing but it seems like it is happening in one or the other. Most photos work just fine, even most from iPhones. There is nothing particularly special about this photo that I can identify, and it is not the only one that fails. I am using ImageMagick for processing through the image_processing gem. I have not yet tried vips.

Full error from Sidekiq:

{"context":"Job raised exception","job":{"class":"ShrinePromoteWorker","args":[229],"retry":true,"queue":"default","jid":"0ba277acb1f59a61ba43be0f","created_at":1576161439.0403652,"enqueued_at":1576161745.372324,"error_message":"\"\\xD6\" from ASCII-8BIT to UTF-8","error_class":"Encoding::UndefinedConversionError","failed_at":1576161441.4497209,"retry_count":3,"retried_at":1576161599.5275307},"jobstr":"{\"class\":\"ShrinePromoteWorker\",\"args\":[229],\"retry\":true,\"queue\":\"default\",\"jid\":\"0ba277acb1f59a61ba43be0f\",\"created_at\":1576161439.0403652,\"enqueued_at\":1576161745.372324,\"error_message\":\"\\\"\\\\xD6\\\" from ASCII-8BIT to UTF-8\",\"error_class\":\"Encoding::UndefinedConversionError\",\"failed_at\":1576161441.4497209,\"retry_count\":3,\"retried_at\":1576161599.5275307}"}
#2

Any chance you could give me the stack trace? At the moment I don’t know where the exception is happening (processing, uploading, metadata extraction etc).

In Shrine I try to promote binary encoding, as from my understanding that’s generally the safest for uploading, but if some code of yours is trying to convert binary file content into UTF-8, that right there could be a problem.

#3

This is what I get if I try to run atomic_promote on the affected file

Download (76ms) – {:storage=>:cache, :location=>"e6f108fae1ad982afd7e3780", :download_options=>{}, :uploader=>PhotoUploader}
Image Dimensions (2ms) – {:io=>Tempfile, :uploader=>PhotoUploader}
MIME Type (32ms) – {:io=>Tempfile, :uploader=>PhotoUploader}
Metadata (38ms) – {:storage=>:store, :io=>Tempfile, :uploader=>PhotoUploader}
Upload (68ms) – {:storage=>:store, :location=>"image/231/file/detail-7cfb8ade672011419f8bd3ede0dc667b.jpg", :io=>Tempfile, :upload_options=>{:acl=>"public-read"}, :uploader=>PhotoUploader}
Image Dimensions (2ms) – {:io=>Tempfile, :uploader=>PhotoUploader}
MIME Type (18ms) – {:io=>Tempfile, :uploader=>PhotoUploader}
Metadata (23ms) – {:storage=>:store, :io=>Tempfile, :uploader=>PhotoUploader}
Upload (51ms) – {:storage=>:store, :location=>"image/231/file/square_thumbnail-13c1fe4aac4e74a139528cd6a46ee698.jpg", :io=>Tempfile, :upload_options=>{:acl=>"public-read"}, :uploader=>PhotoUploader}
Image Dimensions (2ms) – {:io=>Tempfile, :uploader=>PhotoUploader}
MIME Type (17ms) – {:io=>Tempfile, :uploader=>PhotoUploader}
Metadata (23ms) – {:storage=>:store, :io=>Tempfile, :uploader=>PhotoUploader}
Upload (53ms) – {:storage=>:store, :location=>"image/231/file/thumbnail-15648c02b203d9e31ff13906d7a7d005.jpg", :io=>Tempfile, :upload_options=>{:acl=>"public-read"}, :uploader=>PhotoUploader}
Upload (74ms) – {:storage=>:store, :location=>"image/231/file/a9c31cbb128a19ff9a75e63d1963e40b.jpg", :io=>PhotoUploader::UploadedFile, :upload_options=>{:acl=>"public-read"}, :uploader=>PhotoUploader}
   (0.5ms)  BEGIN
  Image Load (15.5ms)  SELECT  "images".* FROM "images" WHERE "images"."id" = $1 LIMIT $2 FOR UPDATE  [["id", 231], ["LIMIT", 1]]
   (0.8ms)  ROLLBACK
Traceback (most recent call last):
        1: from (irb):19
Encoding::UndefinedConversionError ("\xD6" from ASCII-8BIT to UTF-8)

PhotoUploader is trying to do this processing:

  Attacher.derivatives_processor do |original|
    magick = ImageProcessing::MiniMagick.source(original)

    {
      detail: magick.resize_to_limit(1360, 1360).auto_orient.saver(quality: 85).call,
      square_thumbnail: magick.resize_to_fill(300, 300).auto_orient.saver(quality: 85).call,
      thumbnail: magick.resize_to_limit(240, 240).auto_orient.saver(quality: 85).call,
    }
  end

I can also give you the stack trace from Sidekiq when it runs the worker, but I feel like since atomic_promote all by itself is throwing the error, the sidekiq log would probably just provide more noise than actual value.

#4

FWIW I also tried this with VIPS instead of ImageMagick and the same error occurred, so I am thinking it probably doesn’t have to do with the processing.

#5

Here’s the full stack trace from sidekiq

2019-12-12T18:37:06.784Z pid=1 tid=gp1ytfvhd class=ShrinePromoteWorker jid=da08d1c41e5b0fd27d7d727e INFO: start
2019-12-12T18:37:09.379Z pid=1 tid=gp1ytfvhd class=ShrinePromoteWorker jid=da08d1c41e5b0fd27d7d727e elapsed=2.595 INFO: fail
2019-12-12T18:37:09.380Z pid=1 tid=gp1ytfvhd WARN: {"context":"Job raised exception","job":{"class":"ShrinePromoteWorker","args":[233],"retry":true,"queue":"default","jid":"da08d1c41e5b0fd27d7d727e","created_at":1576175826.780594,"enqueued_at":1576175826.7817605},"jobstr":"{\"class\":\"ShrinePromoteWorker\",\"args\":[233],\"retry\":true,\"queue\":\"default\",\"jid\":\"da08d1c41e5b0fd27d7d727e\",\"created_at\":1576175826.780594,\"enqueued_at\":1576175826.7817605}"}
2019-12-12T18:37:09.380Z pid=1 tid=gp1ytfvhd WARN: Encoding::UndefinedConversionError: "\xC9" from ASCII-8BIT to UTF-8
2019-12-12T18:37:09.380Z pid=1 tid=gp1ytfvhd WARN: /usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/core_ext/object/json.rb:38:in `encode'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/core_ext/object/json.rb:38:in `to_json'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/core_ext/object/json.rb:38:in `to_json'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/json/encoding.rb:57:in `to_json'
/usr/local/bundle/gems/json-2.2.0/lib/json/common.rb:224:in `generate'
/usr/local/bundle/gems/json-2.2.0/lib/json/common.rb:224:in `generate'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/json/encoding.rb:102:in `stringify'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/json/encoding.rb:35:in `encode'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/json/encoding.rb:22:in `encode'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/type/json.rb:18:in `serialize'
/usr/local/bundle/gems/activemodel-5.2.3/lib/active_model/type/helpers/mutable.rb:8:in `cast'
/usr/local/bundle/gems/activemodel-5.2.3/lib/active_model/attribute.rb:175:in `type_cast'
/usr/local/bundle/gems/activemodel-5.2.3/lib/active_model/attribute.rb:42:in `value'
/usr/local/bundle/gems/activemodel-5.2.3/lib/active_model/attribute.rb:156:in `changed_from_assignment?'
/usr/local/bundle/gems/activemodel-5.2.3/lib/active_model/attribute.rb:59:in `changed?'
/usr/local/bundle/gems/activemodel-5.2.3/lib/active_model/attribute_mutation_tracker.rb:49:in `changed?'
/usr/local/bundle/gems/activemodel-5.2.3/lib/active_model/attribute_mutation_tracker.rb:43:in `block in any_changes?'
/usr/local/bundle/gems/activemodel-5.2.3/lib/active_model/attribute_mutation_tracker.rb:43:in `any?'
/usr/local/bundle/gems/activemodel-5.2.3/lib/active_model/attribute_mutation_tracker.rb:43:in `any_changes?'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/attribute_methods/dirty.rb:104:in `has_changes_to_save?'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/timestamp.rb:118:in `should_record_timestamps?'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/timestamp.rb:106:in `_update_record'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/persistence.rb:705:in `create_or_update'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/callbacks.rb:342:in `block in create_or_update'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:132:in `run_callbacks'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/callbacks.rb:342:in `create_or_update'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/persistence.rb:275:in `save'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/validations.rb:46:in `save'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/transactions.rb:310:in `block (2 levels) in save'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/database_statements.rb:265:in `transaction'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/transactions.rb:212:in `transaction'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/transactions.rb:310:in `block in save'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/transactions.rb:325:in `rollback_active_record_state!'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/transactions.rb:309:in `save'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/suppressor.rb:44:in `save'
/usr/local/bundle/gems/shrine-3.1.0/lib/shrine/plugins/activerecord.rb:102:in `activerecord_persist'
/usr/local/bundle/gems/shrine-3.1.0/lib/shrine/plugins/atomic_helpers.rb:112:in `call'
/usr/local/bundle/gems/shrine-3.1.0/lib/shrine/plugins/atomic_helpers.rb:112:in `abstract_persist'
/usr/local/bundle/gems/shrine-3.1.0/lib/shrine/plugins/atomic_helpers.rb:79:in `block in abstract_atomic_persist'
/usr/local/bundle/gems/shrine-3.1.0/lib/shrine/plugins/atomic_helpers.rb:104:in `block in abstract_reload'
/usr/local/bundle/gems/shrine-3.1.0/lib/shrine/plugins/activerecord.rb:108:in `block in activerecord_reload'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `block in transaction'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
/usr/local/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `transaction'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/transactions.rb:212:in `transaction'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/transactions.rb:301:in `transaction'
/usr/local/bundle/gems/shrine-3.1.0/lib/shrine/plugins/activerecord.rb:108:in `activerecord_reload'
/usr/local/bundle/gems/shrine-3.1.0/lib/shrine/plugins/atomic_helpers.rb:100:in `call'
/usr/local/bundle/gems/shrine-3.1.0/lib/shrine/plugins/atomic_helpers.rb:100:in `abstract_reload'
/usr/local/bundle/gems/shrine-3.1.0/lib/shrine/plugins/atomic_helpers.rb:72:in `abstract_atomic_persist'
/usr/local/bundle/gems/shrine-3.1.0/lib/shrine/plugins/atomic_helpers.rb:52:in `abstract_atomic_promote'
/usr/local/bundle/gems/shrine-3.1.0/lib/shrine/plugins/_persistence.rb:28:in `block (2 levels) in configure'
/brownie/app/workers/shrine_promote_worker.rb:11:in `perform'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/processor.rb:193:in `execute_job'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/processor.rb:161:in `block (2 levels) in process'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/middleware/chain.rb:138:in `block in invoke'
/brownie/config/initializers/sidekiq.rb:5:in `call'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
/usr/local/bundle/gems/rollbar-2.22.1/lib/rollbar/plugins/sidekiq/plugin.rb:11:in `call'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
/usr/local/bundle/gems/sidekiq-pro-5.0.1/lib/sidekiq/batch/middleware.rb:54:in `call'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/middleware/chain.rb:143:in `invoke'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/processor.rb:160:in `block in process'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/processor.rb:133:in `block (6 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/job_retry.rb:110:in `local'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/processor.rb:132:in `block (5 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/rails.rb:43:in `block in call'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/execution_wrapper.rb:87:in `wrap'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/reloader.rb:73:in `block in wrap'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/execution_wrapper.rb:87:in `wrap'
/usr/local/bundle/gems/activesupport-5.2.3/lib/active_support/reloader.rb:72:in `wrap'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/rails.rb:42:in `call'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/processor.rb:128:in `block (4 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/processor.rb:254:in `stats'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/processor.rb:123:in `block (3 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/job_logger.rb:13:in `call'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/processor.rb:122:in `block (2 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/job_retry.rb:78:in `global'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/processor.rb:121:in `block in dispatch'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/logger.rb:10:in `with'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/job_logger.rb:33:in `prepare'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/processor.rb:120:in `dispatch'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/processor.rb:159:in `process'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/processor.rb:78:in `process_one'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/processor.rb:68:in `run'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/util.rb:17:in `watchdog'
/usr/local/bundle/gems/sidekiq-6.0.1/lib/sidekiq/util.rb:26:in `block in safe_thread'
#6

Thanks for the stack trace. From what I see, this error is happening when Shrine calls ActiveRecord::Base#save, and it seems to be coming from ActiveSupport’s JSON serialization as part of ActiveRecord’s JSON typecasting (you’re using a JSON column, right?).

So, my guess is that Shrine is attempting to write binary data into the #<attachment>_data column on the model, which cannot be converted into UTF-8 encoding (which is needed for JSON serialization). If that’s the case, then it’s probably the filename metadata value, though it’s strange that the error happens only in the background job. It could be some other metadata, e.g. if you’re extracting image EXIF data, there could be some binary content there.

I would recommend that you add the following line before the attacher.atomic_promote call:

pp attacher.data
# or 
pp attacher.record.send(attacher.attribute)

and see in the output if you can find any binary data (i.e. strings such as \xC9). If you find something, try to find a way to omit that or encode it to UTF-8. That’s the only thing that comes to my mind at the moment.

#7

Seems to be related to the EXIF information - I have this in my uploader

  add_metadata :exif do |io|
    Exif::Data.new(io).to_h
  rescue Exif::NotReadable
    {}
  end

If I take that out the error does not occur. So I’m guessing there’s something binary in the exif that isn’t getting handled properly.

#8

It turns out that there are a few binary fields in the EXIF data of iPhone XS photos which the code I pasted (which is straight from the shrine documentation) can’t cope with. I’d suggest that this case should be handled by the add_metadata plugin since this is probably a pretty common thing people will run into. In the meantime I’m just going to pull out only the exif data I care about and ignore all the binary stuff.