This project is archived and is in readonly mode.

#900 ✓resolved
Luca Guidi

Add magic encoding comment to generated files

Reported by Luca Guidi | August 25th, 2008 @ 11:30 AM | in 2.x

I'm using memcached store and UTC time zone.


comment = Comment.first
Rails.cache.write('comment', comment)
cached_comment = Rails.cache.read('comment')

comment.updated_at # => "2008-08-25 10:05:32" # UTC
cached_comment.updated_at # => "2008-08-25 10:05:32" # UTC



comment.update_attributes :text => 'Nice post!'
Rails.cache.write('comment', comment)
cached_comment = Rails.cache.read('comment')

comment.updated_at # => "2008-08-25 10:06:09" # UTC
cached_comment.updated_at # => 2008-08-25 12:06:09" # local time

I believe it's a bug, because it doesn't behaves the same with other caching systems (:file_store and :memory_store). I experienced this problem with Rails 2.1.0 and current edge.

Comments and changes to this ticket

  • Geoff Buesing

    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?

  • Luca Guidi

    Luca Guidi 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.

  • Luca Guidi

    Luca Guidi 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

    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?

  • Luca Guidi
  • Geoff Buesing

    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?

  • Luca Guidi

    Luca Guidi 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

    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

    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.

  • Luca Guidi

    Luca Guidi 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

    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

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

    • no changes were found...
  • Luca Guidi
  • Michael Koziarski

    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

    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

    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.)

  • Luca Guidi

    Luca Guidi 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.

  • Luca Guidi
  • Luca Guidi

    Luca Guidi August 27th, 2008 @ 10:35 AM

    • Tag changed from activesupport, bug to activesupport, bug, patch, tested

    I attached a patch.

  • Repository

    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

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

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

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

  • Geoff Buesing

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

    • State changed from “new” to “resolved”
  • Michael Koziarski

    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

    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...

  • Ryan Bigg

    Ryan Bigg October 9th, 2010 @ 10:13 PM

    • Tag cleared.
    • Importance changed from “” to “Low”

    Automatic cleanup of spam.

  • Ryan Bigg

    Ryan Bigg October 21st, 2010 @ 03:39 AM

    Automatic cleanup of spam.

  • bingbing
  • bingbing
  • links london

Create your profile

Help contribute to this project by taking a few moments to create your personal profile. Create your profile »

<h2 style="font-size: 14px">Tickets have moved to Github</h2>

The new ticket tracker is available at <a href="https://github.com/rails/rails/issues">https://github.com/rails/rails/issues</a>

Attachments

Referenced by

Pages