Ruby on Rails

Comments and changes to this ticket

• 

  Geoff Buesing August 25th, 2008 @ 02:45 PM

  From your post on the Core list, it sounds like you're setting config.time_zone, is that correct? If so, you'll need the bugfix to TimeWithZone Marshaling in 2-1-stable, which isn't in the 2.1.0 gem release:

  http://github.com/rails/rails/co...

  Also, please note this behavior with Ruby's marshaling of Time instances -- you'll always get a Time.local instance, even if you're marshaling a Time.utc instance:

  
  >> t = Time.utc(2000,1,1)
  => Sat Jan 01 00:00:00 UTC 2000
  >> tmarshaled = Marshal.dump t
  => "\004\bu:\tTime\r \000\031\200\000\000\000\000"
  >> t2 = Marshal.load tmarshaled
  => Fri Dec 31 18:00:00 -0600 1999
  

  Could you check the class of cached_comment.updated_at through the steps in your example and see if you're consistently dealing with either a Time or a TimeWithZone instance?

• 

  jodosha August 25th, 2008 @ 03:19 PM

  I know this is the behavior of Ruby's marshaling, but it doesn't seems a consistent solution. Because: * This affects only the Memcached store * The first time I write the object to the cache it correctly stores the updated_at value (UTC), but following accesses will return local time. * The database values and cached values timestamps are different.

  The linked commit doesn't solve this problem, because it affects both 2.1.0 and edge.

  The updatet_at class is always TimeWithZone.

• 

  jodosha August 25th, 2008 @ 03:54 PM

  It seems like Marshal can't properly (un)serialize models with @changed_attributes, maybe because timestamps inside that hash, are instances of Time instead of TimeWithZone.

  http://pastie.org/259472

• 

  Geoff Buesing August 25th, 2008 @ 04:28 PM

  Just to narrow things down -- if you comment out config.time_zone in environment.rb, and add

  config.active_record.default_timezone = :utc

  does the problem still occur?

• 

  jodosha August 25th, 2008 @ 04:41 PM

  Yes it still occurs.

• 

  Geoff Buesing August 25th, 2008 @ 05:52 PM

  Aha ok. That rules out TimeWithZone as a player here.

  If you just write a plain Time.utc instance to the cache, and then retrieve it, what does it come back as?

• 

  jodosha August 25th, 2008 @ 07:11 PM

  
  >> utc = Time.utc(2000, 1, 1)
  => Sat Jan 01 00:00:00 UTC 2000
  >> Rails.cache.write('utc', utc)
  => true
  >> Rails.cache.read('utc')
  => Sat Jan 01 01:00:00 +0100 2000
  

• 

  Geoff Buesing August 25th, 2008 @ 07:45 PM

  Ok, so I'm thinking the problem is this:

  In your example, when you read the object from the db and immediately store it in the cache, updated_at is still a string, because datetime attributes aren't cast to Time objects until read_attribute is called. So when the object is marshaled and then unmarshaled, the string value of updated_at unmarshals fine.

  However, when you update the object, updated_at is set to a Time object (Time.now.utc) -- so when you marshal and unmarshal, you get a Time.local object instead of a Time.utc object. This Time.local object will send the wrong value to the database if AR default_timezone is :utc (which it will be set to if you set config.time_zone).

  How to fix this? One way would be, when storing an AR object in the db, call #utc on all time column values before we call #to_s(:db) on them, if AR default_timezone is :utc.

• 

  Geoff Buesing August 25th, 2008 @ 08:18 PM

  ...but of course that solution might break other apps that rely on the existing behavior, so maybe that's not such a good solution.

• 

  jodosha August 25th, 2008 @ 09:09 PM

  Calling explicitly #updated_at should force the type casting. Is it right? But, even if I force the type casting, invoking #updated_at, before cache the object, it returns the right value (UTC).

  I also tried to directly assign the value and store the model again, it works fine (case 2), but when I save the object and re-cache, it returns the local time (case 3).

  
  >> comment = Comment.first
  => #<Comment id: 865423346, post_id: 1, text: "Nice post.", created_at: "2008-08-25 19:51:22", updated_at: "2008-08-25 19:51:22">
  >> comment.updated_at # forcing type casting with #read_attribute
  => Mon, 25 Aug 2008 19:51:22 UTC +00:00
  >> Rails.cache.write('comment', comment)
  => true
  >> Rails.cache.read('comment')
  => #<Comment id: 865423346, post_id: 1, text: "Nice post.", created_at: "2008-08-25 19:51:22", updated_at: "2008-08-25 19:51:22"> # UTC time, right
  
  
  
  >> comment.updated_at = Time.now.utc # forcing UTC time
  => Mon Aug 25 19:55:27 UTC 2008
  >> Rails.cache.write('comment', comment)
  => true
  >> Rails.cache.read('comment')
  => #<Comment id: 865423346, post_id: 1, text: "Nice post.", created_at: "2008-08-25 19:51:22", updated_at: "2008-08-25 19:55:27"> # UTC time, right
  
  
  
  >> comment.save
  => true
  >> Rails.cache.write('comment', comment)
  => true
  >> Rails.cache.read('comment')
  => #<Comment id: 865423346, post_id: 1, text: "Nice post.", created_at: "2008-08-25 19:51:22", updated_at: "2008-08-25 21:59:26"> # local time, wrong
  

  Anyway, I think it's a Ruby marshaling bug:

  
  >> utc = Time.now.utc
  => Mon Aug 25 20:07:39 UTC 2008
  >> marshaled = Marshal.dump utc
  => "\004\bu:\tTime\r4\037\e\200]\377q\036"
  >> Marshal.load marshaled
  => Mon Aug 25 22:07:39 +0200 2008
  

• 

  Geoff Buesing August 26th, 2008 @ 02:11 PM

  Agreed, this issue is definitely due to the Ruby's Time marshaling ignoring the zone.

  I think my diagnosis above is correct -- in the example below, note how the updated_at attribute in the @attributes hash remains a string ("2008-08-26 12:50:54") even after I call the #updated_at method, but then becomes a Time object (Tue Aug 26 12:55:08 UTC 2008) after I #update_attributes:

  
  # in environment.rb
  # config.time_zone = 'UTC' # this is commented out
  # config.active_record.default_timezone = :utc
  
  >> p = Post.first
  => #<Post id: 1, title: "testing", posted_at: "2000-01-01 06:00:00", created_at: "2008-06-28 04:24:53", updated_at: "2008-08-26 12:50:54">
  >> p.instance_variable_get('@attributes')
  => {"updated_at"=>"2008-08-26 12:50:54", "title"=>"testing", "id"=>"1", "posted_at"=>"2000-01-01 06:00:00", "created_at"=>"2008-06-28 04:24:53"}
  >> p.updated_at
  => Tue Aug 26 12:50:54 UTC 2008
  >> p.instance_variable_get('@attributes')
  => {"updated_at"=>"2008-08-26 12:50:54", "title"=>"testing", "id"=>"1", "posted_at"=>"2000-01-01 06:00:00", "created_at"=>"2008-06-28 04:24:53"}
  >> p.update_attributes :title => 'test123'
  => true
  >> p.instance_variable_get('@attributes')
  => {"updated_at"=>Tue Aug 26 12:55:08 UTC 2008, "title"=>"test123", "id"=>"1", "posted_at"=>"2000-01-01 06:00:00", "created_at"=>"2008-06-28 04:24:53"}
  

  ...and here's an example of the bug appearing when you marshal an AR instance:

  
  >> p=Post.first
  => #<Post id: 1, title: "test", posted_at: "2000-01-01 06:00:00", created_at: "2008-06-28 04:24:53", updated_at: "2008-06-28 04:24:53">
  >> p.update_attributes :title => 'foo'
  => true
  >> p.updated_at
  => Tue Aug 26 12:46:56 UTC 2008
  >> marshaled = Marshal.dump p
  => "\004\bo:\tPost\t:\f@errorso:\031ActiveRecord::Errors\a;\006{\000:\n@base@\000:\020@attributes{\n\"\017updated_atu:\tTime\rL\037\e\200\220X\211\273\"\ntitle\"\bfoo\"\aid\"\0061\"\016posted_at\"\0302000-01-01 06:00:00\"\017created_at\"\0302008-06-28 04:24:53:\026@attributes_cache{\006\"\017updated_at@\n:\030@changed_attributes{\000"
  >> unmarshaled = Marshal.load marshaled
  => #<Post id: 1, title: "foo", posted_at: "2000-01-01 06:00:00", created_at: "2008-06-28 04:24:53", updated_at: "2008-08-26 07:46:56">
  >> unmarshaled.updated_at
  => Tue Aug 26 07:46:56 -0500 2008
  

• 

  Geoff Buesing August 26th, 2008 @ 02:11 PM

  • no changes were found...
• 

  jodosha August 26th, 2008 @ 03:43 PM

  This bug was solved in Ruby 1.9: http://eigenclass.org/hiki.rb?Ch...

• 

  Michael Koziarski August 26th, 2008 @ 03:47 PM

  Perhaps the 'right' fix is to make sure that TimeWithZone marshalls correctly, and encourage people to switch to timezone_aware_attributes?

• 

  Geoff Buesing August 26th, 2008 @ 05:28 PM

  Glad to hear this is solved in 1.9.

  If we used TimeWithZone objects to set created_at and updated_at timestamps (via a call to #in_time_zone), the only vulnerable points for the Time marshaling bug would be for attributes where you explicitly opt out of time_zone_aware_attributes. I guess an explicit warning in the docs would be the best we could do for this case.

  An alternate approach would be, when setting created_at/updated_at, explicitly call #to_s(:db) on these values, so the attributes hash just contains strings (which will marshal without problem.)

• 

  Geoff Buesing August 27th, 2008 @ 07:48 AM

  Thinking this through -- really, given that 1.9 fixes Time marshaling, we can consider the 1.8 behavior buggy, and fix it in ActiveSupport.

  I came up with this fix:

  
  class Time
    if RUBY_VERSION < '1.9'
      class << self
        alias_method :_original_load, :_load
  
        def _load(marshaled_time)
          time = _original_load(marshaled_time)
          if time.instance_variable_get('@marshal_with_utc_coercion')
            time.send(:remove_instance_variable, '@marshal_with_utc_coercion')
            time.utc
          else
            time
          end
        end
      end
  
      alias_method :_original_dump, :_dump
  
      def _dump(*args)
        instance_variable_set('@marshal_with_utc_coercion', true) if utc?
        _original_dump(*args)
      end
    end
  end
  
  
  utc = Time.now.utc
  utc_marshaled = Marshal.dump utc
  utc_unmarshaled = Marshal.load utc_marshaled
  puts utc_unmarshaled  # => Wed Aug 27 06:24:11 UTC 2008
  
  local = Time.now
  local_marshaled = Marshal.dump local
  local_unmarshaled = Marshal.load local_marshaled
  puts local_unmarshaled  # => Wed Aug 27 01:24:11 -0500 2008
  

  I'll pull this fix in, unless anyone can think of a good reason not to. This should fix the problem originally identified with this ticket, plus other use cases that would currently be broken (e.g., storing a utc timestamp in the cache.)

• 

  jodosha August 27th, 2008 @ 10:12 AM

  I suggest a bit different code, because the #instance_variable_get call generates a warning if the time isn't UTC: warning: instance variable @marshal_with_utc_coercion not initialized.

  
  class Time
    if RUBY_VERSION < '1.9'
      class << self
        alias_method :_original_load, :_load
        def _load(marshaled_time)
          time = _original_load(marshaled_time)
          utc = time.send(:remove_instance_variable, '@marshal_with_utc_coercion')
          utc ? time.utc : time
        end
      end
  
      alias_method :_original_dump, :_dump
      def _dump(*args)
        instance_variable_set('@marshal_with_utc_coercion', utc?)
        _original_dump(*args)
      end
    end
  end
  

  Of course if you don't like, we can surround with #silence_warnings.

• 

  jodosha August 27th, 2008 @ 10:29 AM

  • no changes were found...

  • 0001-Fix-Ruby-1.9-Time-UTC-marshaling-bug.patch 2.2 KB
• 

  jodosha August 27th, 2008 @ 10:35 AM

  • → Tag changed from “activesupport bug” to “activesupport bug patch tested”

  I attached a patch.

• 

  Repository August 27th, 2008 @ 02:59 PM

  • → State changed from “new” to “resolved”

  (from [ce65a05c5b027175c3c541055081f82c8bfc36bf]) Fix Ruby's Time marshaling bug in pre-1.9 versions of Ruby: utc instances are now correctly unmarshaled with a utc zone instead of the system local zone [#900 state:resolved] http://github.com/rails/rails/co...

• 

  Geoff Buesing August 27th, 2008 @ 03:02 PM

  • → Tag changed from “activesupport bug patch tested” to “activesupport bug”
  • → State changed from “resolved” to “new”

  Good catch on the warning, and thanks for the patch. I added logic to cope with frozen objects.

• 

  Geoff Buesing August 27th, 2008 @ 03:03 PM

  • → State changed from “new” to “resolved”
• 

  Michael Koziarski August 27th, 2008 @ 03:05 PM

  Geoff: Unless there's a reason not to, it seems like something we should merge into 2-1-stable too

• 

  Repository August 27th, 2008 @ 03:14 PM

  (from [4d71e99d1fc1f57900288e008d7528c339138cf0]) Fix Ruby's Time marshaling bug in pre-1.9 versions of Ruby: utc instances are now correctly unmarshaled with a utc zone instead of the system local zone [#900 state:resolved] http://github.com/rails/rails/co...