association_versioning with ignore_log_data: true causes MissingAttributeError

[dmills-yesware]

I'm taking logidze for a spin and it seems to be a great fit for our needs, but I've encountered what appears to be a bug. With association_versioning and ignore_log_data turned on, after retrieving a copy of the model at a given point in time using at, I'm then unable to retrieve the associated records, instead receiving the error ActiveModel::MissingAttributeError: missing attribute: log_data.

Ruby version: 2.3.5
ActiveRecord version: 4.2.10

The issue vanishes if I either turn off ignore_log_data on the associated model (ie. the Comment model in the example below) or disable association versioning. So far I haven't found a way to work around the issue.

Steps to reproduce, based on the association tracking example:

Migrations

# Post
class CreatePosts < ActiveRecord::Migration
  def change
    create_table :posts do |t|
      t.string :title
      t.string :content
      t.timestamps null: false
    end
  end
end

# Comment
class CreateComments < ActiveRecord::Migration
  def change
    create_table :comments do |t|
      t.string :body
      t.references :post, index: true, foreign_key: true
      t.timestamps null: false
    end
  end
end

Models

class Post < ActiveRecord::Base
  has_logidze ignore_log_data: true
  has_many :comments
end

class Comment < ActiveRecord::Base
  has_logidze ignore_log_data: true
  belongs_to :post
end

Code to reproduce

[24] pry(main)> p = Post.create(title: "New Post", content: "Bug hunting")

=> #<Post:0x00007fb7ac642c18
 id: 4,
 title: "New Post",
 content: "Bug hunting",
 created_at: Mon, 11 Mar 2019 12:28:08 UTC +00:00,
 updated_at: Mon, 11 Mar 2019 12:28:08 UTC +00:00,
 log_data: nil>

[25] pry(main)> p = Post.with_log_data.last

=> #<Post:0x00007fb7ad2bbd78
 id: 4,
 title: "New Post",
 content: "Bug hunting",
 created_at: Mon, 11 Mar 2019 12:28:08 UTC +00:00,
 updated_at: Mon, 11 Mar 2019 12:28:08 UTC +00:00,
 log_data:
  #<Logidze::History:0x00007fb7afa619e0
   @data=
    {"h"=>
      [{"c"=>
         {"id"=>4,
          "title"=>"New Post",
          "content"=>"Bug hunting",
          "created_at"=>"2019-03-11T12:28:08.089259",
          "updated_at"=>"2019-03-11T12:28:08.089259"},
        "v"=>1,
        "ts"=>1552307288089}],
     "v"=>1}>>

[26] pry(main)> p.comments.create(body: "First comment")

=> #<Comment:0x00007fb7af89a620
 id: 3,
 body: "First comment",
 post_id: 4,
 created_at: Mon, 11 Mar 2019 12:28:46 UTC +00:00,
 updated_at: Mon, 11 Mar 2019 12:28:46 UTC +00:00,
 log_data: nil>

[27] pry(main)> p.at(time: Time.now)

=> #<Post:0x00007fb7ad2bbd78
 id: 4,
 title: "New Post",
 content: "Bug hunting",
 created_at: Mon, 11 Mar 2019 12:28:08 UTC +00:00,
 updated_at: Mon, 11 Mar 2019 12:28:08 UTC +00:00,
 log_data:
  #<Logidze::History:0x00007fb7afa619e0
   @data=
    {"h"=>
      [{"c"=>
         {"id"=>4,
          "title"=>"New Post",
          "content"=>"Bug hunting",
          "created_at"=>"2019-03-11T12:28:08.089259",
          "updated_at"=>"2019-03-11T12:28:08.089259"},
        "v"=>1,
        "ts"=>1552307288089}],
     "v"=>1},
   @versions=
    [#<Logidze::History::Version:0x00007fb7af92ba30
      @data=
       {"c"=>
         {"id"=>4,
          "title"=>"New Post",
          "content"=>"Bug hunting",
          "created_at"=>"2019-03-11T12:28:08.089259",
          "updated_at"=>"2019-03-11T12:28:08.089259"},
        "v"=>1,
        "ts"=>1552307288089}>]>>

[28] pry(main)> p.comments.length

ActiveModel::MissingAttributeError: missing attribute: log_data
from /Users/dmills/.rvm/gems/ruby-2.3.5@yesware/gems/activerecord-4.2.10/lib/active_record/attribute_methods/read.rb:93:in `block in _read_attribute'

I hope that helps. Let me know if I can provide any additional details that might be useful. And thanks for the great work on this library!

[palkan]

When you call p.comments.length the comments association is not loaded yet, so we try to load it and rewind the state calling the #at method.

And it fails since the ignore_log_data is true for the Comment.

You need to use with_log_data here as well, i.e. p.comments.with_log_data.length.

Which seems confusing.

@DmitryTsepelev Maybe, we should apply with_log_data to associations automatically if log_data is defined for the owner?

[DmitryTsepelev]

Makes sense. I'll take a closer look later this week, @dmills-yesware thanks for pointing this out!

[dmills-yesware]

Thanks for the quick response!

You need to use with_log_data here as well, i.e. p.comments.with_log_data.length

Ah, excellent. I had tried that, but not before first trying to load comments on the instance without using with_log_data.

[34] pry(main)> p.comments.length

ActiveModel::MissingAttributeError: missing attribute: log_data
from /Users/dmills/.rvm/gems/ruby-2.3.5@yesware/gems/activerecord-4.2.10/lib/active_record/attribute_methods/read.rb:93:in `block in _read_attribute'

[35] pry(main)> p.comments.with_log_data.length

ActiveModel::MissingAttributeError: missing attribute: log_data
from /Users/dmills/.rvm/gems/ruby-2.3.5@yesware/gems/activerecord-4.2.10/lib/active_record/attribute_methods/read.rb:93:in `block in _read_attribute'

As long as the first attempt to load the relation includes with_log_data then it works:

[40] pry(main)> Post.with_log_data.last.at(time: Time.now).comments.with_log_data.at(time: Time.now).length

=> 3

Worth noting: It does appear that I need to repeat the at on the comments relation in order to get the correct historical view of the comments at the same point in time as the Post. That's probably expected with the way things are built, but it might also be cool if the API were made to load the relation using the same with_log_data and at setting as the parent model, so that it's seamless.

Thanks again.

[palkan]

It does appear that I need to repeat the at on the comments relation in order to get the correct historical view of the comments at the same point in time as the Post. That's probably expected with the way things are built

Looks like a bug. Associations should inherit the at value automatically.

[DmitryTsepelev]

@dmills-yesware FYI I think I have a solution as a part of my ongoing PR - I decided to avoid making a separate one because that PR touches ignore_log_data codebase a lot

[DmitryTsepelev]

Fixed in 0.10.0, @palkan I guess we can close this issue