Odd behaviour with sidekiq returned jid on a mailer when pushing into a serialised field

Question

I am getting some odd behaviour when trying to push a returned jid from a worker into a serialised field on a model. Best explained by this code:

class Foo < ActiveRecord::Base
  serialize :jids, Array

  def do_job
    test_jids = []

    jids << "s"
    test_jids << "s"
    Rails.logger.info("s has been pushed")
    Rails.logger.info(jids)
    Rails.logger.info(test_jids)

    jids << BarWorker.perform_in(10.minutes, self.id)
    test_jids << BarWorker.perform_in(10.minutes, self.id)
    Rails.logger.info("normal worker has been pushed")
    Rails.logger.info(jids)
    Rails.logger.info(test_jids)

    jids << FooMailer.delay_for(10.minutes).confirm_foo(self)
    test_jids << FooMailer.delay_for(10.minutes).confirm_foo(self)
    Rails.logger.info("mailer worker id pushed")
    Rails.logger.info(jids)
    Rails.logger.info(test_jids)

    jids
  end
end

Expected logging:

s has been pushed
["s"]
["s"]

normal worker has been pushed
["s", "6d25faf98b6448a43e1d3bb5"]
["s", "7144ceab11ece07ae352ffb9"]

mailer worker id pushed
["s", "6d25faf98b6448a43e1d3bb5", "54c4634bfc11ec1adad926da"]
["s", "7144ceab11ece07ae352ffb9", "3d0bb94e0411a04ab0339f68"]

Actual logging.

s has been pushed
["s"]
["s"]

normal worker has been pushed
["s", "243675806204134e6f05abaa"]
["s", "1444f558d7582df1000c6f4b"]

mailer worker id pushed
["s", "243675806204134e6f05abaa"]
["s", "1444f558d7582df1000c6f4b", "c0878213a8ea5f783c30e666"]

The job id for the mailer has not been pushed into the jids attribute on foo.

In the confusion I went a bit hacky and wrote this method on Foo

def do_job_with_assignment
  test_jids = []

  jids << "s"
  test_jids << "s"
  Rails.logger.info("s has been pushed")
  Rails.logger.info(jids)
  Rails.logger.info(test_jids)


  bar_worker_jid = BarWorker.perform_in(10.minutes, self.id)
  jids << bar_worker_jid

  test_bar_worker_jid = BarWorker.perform_in(10.minutes, self.id)
  test_jids << test_bar_worker_jid
  Rails.logger.info("normal worker has been pushed")
  Rails.logger.info(jids)
  Rails.logger.info(test_jids)

  foo_mailer_jid = FooMailer.delay_for(10.minutes).confirm_foo(self)
  jids << foo_mailer_jid

  test_foo_mailer_jid = FooMailer.delay_for(10.minutes).confirm_foo(self)
  test_jids << test_foo_mailer_jid
  Rails.logger.info("mailer worker id pushed")
  Rails.logger.info(jids)
  Rails.logger.info(test_jids)

  jids
end

Now this does produce the expected logging.

Apart from the obvious, what is the difference between the two?

Edit:

Nobody claimed the bounty, i want to take this further, but im not sure where the problem lies. Anyone suggest a good place to start?

Edit: Classes

> Foo.new.jids.class
=> Array

> BarWorker.perform_in(10.minutes, 1).class
=> String 

> FooMailer.delay_for(10.minutes).confirm_foo(self).class
=> String

Edit:

Demo app. https://github.com/richkettle/sidekiq-oddities

Answer 1

I think this is because Rails caches attributes for all column types except serialized fields. With this in mind when you call the << method on the getter for jids then Rails fetches the attribute for that field but when you then pass self into the mailer this again calls the getter when serializing in Sidekiq, and overwrites the attribute instance and so the returned value does not get added to the correct jids instance.

I'm not sure I fully understand why this is happening so some exact implementation details may be dodgy there!

This can be fixed/made to work with this version of Rails (4.1.5) by one of the following:

Cache the jids attribute:

class Foo < ActiveRecord::Base
  serialize :jids, Array
  cache_attributes :jids

Use the jids setter:

jids = self.jids << FooMailer.delay_for(10.minutes).confirm_foo(self)

Pass an id or a copy into the mailer:

jids << FooMailer.delay_for(10.minutes).confirm_foo(id)
# or
jids << FooMailer.delay_for(10.minutes).confirm_foo(self.dup)

This is fixed in Rails 4.2 when this code is rewritten, a PR I could find is here: https://github.com/rails/rails/pull/15429