latest release (v0.10.0) breaks db tests

[jonknapp]

Tell us about your environment

Ruby Version: ruby 2.6.3p62 (2019-04-16 revision 67580) [x86_64-darwin18]

Rails Version: Rails 6.0.0.rc1

PostgreSQL Version: PostgreSQL 10.6 on x86_64-pc-linux-musl, compiled by gcc (Alpine 8.2.0) 8.2.0, 64-bit

Logidze Version: v0.10.0

What did you do?

Running tests that rely on test fixtures caused a bunch of failures that were seemingly unrelated to the tests being ran.

What did you expect to happen?

Tests would continue to pass.

What actually happened?

I have a feeling that this may be related to parallel tests and Rails stock test fixtures.

I kept my app on v0.9.0 and also got some recent console errors while trying to set a responsible_id in an ActiveJob. The error output was WARNING: SET LOCAL can only be used in transaction blocks

I realize this isn't a very actionable error, but wanted to bring it up in case others ran into something similar. Feel free to close if it's not helpful.

[palkan]

How do you set responsible_id in jobs? Could you provide an example code?

As I understand, tests fail with v0.10.0 and pass with v0.9.0, right?

It would be helpful to see the ActiveRecord logs for a single failing test. You can enable AR logging by adding the following to your test setup (rails_helper.rb or test_helper.rb):

::ActiveRecord::Base.logger = ::ActiveSupport::LogSubscriber.logger = Logger.new(STDOUT)

Or using a test-prof recipe.

[jonknapp]

For setting responsible_id in tests, I enqueue the job with the user's ID as a param:

class SomeJob < ApplicationJob
  queue_as :default

  def perform(responsible_id, other, things)
    Logidze.with_responsible(responsible_id) do
      api = DoStuff(other, thing)
      api.create_or_update_user!(user)
    end
  end
end

I am using stock Rails tests with fixtures.

You are correct that my app's tests passed in v0.9.0 and started to fail in v0.10.0. I will take a look at your log suggestion tomorrow and come back with some more info.

[jonknapp]

My original assumptions seem to be a bit off. Instead, at least in the first test I dug into, there are differences in how join queries are built for a model that has logidze with version v0.10.0.

Without Logidze, the query begins with SELECT "accounts".* FROM "accounts" INNER JOIN ...

However, when has_logidze is in my Account model, the query changes to SELECT * FROM "accounts" INNER JOIN .... Notice the table prefix is missing which incorrectly returns the id column of the joined table (AccountMembership) instead of the intended Account model.

[jonknapp]

The issue appears to be centralized to the DefaultScopePatch#unscoped method. If I return super instead of the existing line 19 (block_given? ? with_log_data.scoping { yield } : with_log_data) all of the tests pass again. I'll keep digging to see if I can find a solution that keeps the functionality.

[jonknapp]

Changing line 19 to block_given? ? with_log_data.scoping { yield } : super keeps all tests passing in your project as well as my own. I'm guessing there is a reason why the change was made though. Unfortunately, I'm not sure of context at that part of the codebase.

[jonknapp]

If I set Rails.application.config.logidze.ignore_log_data_by_default = true in my app I do run into attribute missing errors in my own app's test suite, so my tweak to use super is not going to cut it as a solution which is what I expected.

If there's any other info I can provide that would be helpful, or things you'd like me to try poking around in, just let me know.

[palkan]

Thanks for the investigation! Really helpful!

That's the breaking line, I think:

logidze/lib/logidze/ignore_log_data.rb

Line 29 in 9f97dc6

select("*")

I gonna add a fix soon; for now you can override with_log_data scope in your model(-s) to smth like:

scope :with_log_data, lambda {
  if ignored_columns == ["log_data"]
    select("#{table_name}.*")
  else
    select(column_names + ["log_data"])
  end
}

[palkan]

This PR (#128) should fix this problem. I'm going to add more improvements in there but feel free to try this branch.

[jonknapp]

Not sure if comments are better here or on your PR at this point, but your PR fixes one of the the initial issues that I submitted, but there are still others in my test suite that seem to fall into two categories.

For my setup, I am not setting Logidze.ignore_log_data_by_default at all and my models use has_logidze without disabling log_data retrieval.

---

1. Arel struct objects in queries (majority of errors)

This one appears to be generating the query with individual columns listed (which is probably what it's supposed to do) but it seems to be adding an Arel ruby object to the query string.

Original Query using v0.9.0

SELECT COUNT(*) FROM "licenses" WHERE "licenses"."account_id" = $1 AND "licenses"."is_archived" = $2  [["account_id", 688319037], ["is_archived", false]]

Bad Query using v0.10.0 with branch fix/select-with-ignore

SELECT COUNT(id, account_id, renewal_sponsor_id, user_id, duration, is_active, is_billable, is_paid, is_renewable, is_trial, invoice_number, license_key, private_notes, product, product_options, public_notes, created_at, updated_at, is_archived, log_data, #<struct Arel::Attributes::Attribute relation=#<Arel::Table:0x00007f8d40feaef0 @name="licenses", @type_caster=#<ActiveRecord::TypeCaster::Map:0x00007f8d40feaf40 @types=License(id: integer, account_id: integer, renewal_sponsor_id: integer, user_id: integer, duration: daterange, is_active: boolean, is_billable: boolean, is_paid: boolean, is_renewable: boolean, is_trial: boolean, invoice_number: string, license_key: uuid, private_notes: text, product: integer, product_options: jsonb, public_notes: text, created_at: datetime, updated_at: datetime, is_archived: boolean, log_data: jsonb)>, @table_alias=nil>, name=:log_data>) FROM "licenses" WHERE "licenses"."account_id" = $1 AND "licenses"."is_archived" = $2  [["account_id", 688319037], ["is_archived", false]]

ActiveRecord::StatementInvalid: PG::SyntaxError: ERROR:  syntax error at or near "Arel"
LINE 1: ...d_at, updated_at, is_archived, log_data, #<struct Arel::Attr...
                                                             ^

    test/models/account_test.rb:43:in `block in <class:AccountTest>'

---

2. "subquery has too many columns" errors

This one seems to add all columns to a subselect query that's seeking the id only.

Original Query using v0.9.0

SELECT "accounts"."name", "accounts"."id" FROM "accounts" WHERE "accounts"."is_archived" = $1 AND "accounts"."id" NOT IN (SELECT "accounts"."id" FROM "accounts" INNER JOIN "engagement_accounts" ON "accounts"."id" = "engagement_accounts"."account_id" WHERE "engagement_accounts"."engagement_id" = $2 AND "accounts"."is_archived" = $3) ORDER BY "accounts"."name" ASC  [["is_archived", false], ["engagement_id", 980190962], ["is_archived", false]]

Bad Query using v0.10.0 with branch fix/select-with-ignore

SELECT "accounts"."name", "accounts"."id" FROM "accounts" WHERE "accounts"."is_archived" = $1 AND "accounts"."id" NOT IN (SELECT "accounts"."id", "accounts"."name", "accounts"."created_at", "accounts"."updated_at", "accounts"."parent_id", "accounts"."salesforce_id", "accounts"."uuid", "accounts"."is_archived", "accounts"."identity_provider_id", log_data, "accounts"."log_data" FROM "accounts" INNER JOIN "engagement_accounts" ON "accounts"."id" = "engagement_accounts"."account_id" WHERE "engagement_accounts"."engagement_id" = $2 AND "accounts"."is_archived" = $3) ORDER BY "accounts"."name" ASC  [["is_archived", false], ["engagement_id", 980190962], ["is_archived", false]]

ActiveRecord::StatementInvalid: PG::SyntaxError: ERROR:  subquery has too many columns
LINE 1: ..."accounts"."is_archived" = $1 AND "accounts"."id" NOT IN (SE...
                                                             ^
    app/controllers/admin/engagement_accounts_controller.rb:41:in `new'
    config/initializers/omniauth.rb:27:in `other_phase'
    test/controllers/admin/engagement_accounts_controller_test.rb:45:in `block in <class:Authorized>'

[palkan]

@jonknapp Finally, I've finished working on #128. Could you please check the master version?

[jonknapp]

After updating to latest master 9249f05:

• ✅ no code changes
• ✅ set Logidze.ignore_log_data_by_default = false in initializer

I changed Logidze.ignore_log_data_by_default = true and had a bunch of ActiveModel::MissingAttributeErrors but I have a feeling that's dealing with my code (or fixtures?) rather than the library functionality. Regardless, I think it's safe to keep this issue closed and if I find something new I can create a new issue.

[palkan]

Thanks!

I changed Logidze.ignore_log_data_by_default = true and had a bunch of ActiveModel::MissingAttributeErrors but I have a feeling that's dealing with my code (or fixtures?) rather than the library functionality

Could you show a stack trace example, please? This exception is raised when you try to access log_data and it hasn't been loaded. I'm curious whether it's happening in the framework/gem code or in the app's own code. If it's the former then we should take this into account somehow.

[jonknapp]

One example is ActiveJob's serialization of a model that has has_logidze in it.

Error:
UserTest#test_will_enqueue_email_to_admins_if_new_user_has_role_of_admin:
ActiveModel::MissingAttributeError: ActiveModel::MissingAttributeError
    /Users/jon/.asdf/installs/ruby/2.6.3/lib/ruby/gems/2.6.0/bundler/gems/logidze-9249f0560acf/lib/logidze/ignore_log_data/missing_attribute_patch.rb:11:in `log_data'
    /Users/jon/.asdf/installs/ruby/2.6.3/lib/ruby/gems/2.6.0/gems/activemodel-6.0.0.rc2/lib/active_model/serialization.rb:137:in `block in serializable_hash'
    /Users/jon/.asdf/installs/ruby/2.6.3/lib/ruby/gems/2.6.0/gems/activemodel-6.0.0.rc2/lib/active_model/serialization.rb:137:in `each'
    /Users/jon/.asdf/installs/ruby/2.6.3/lib/ruby/gems/2.6.0/gems/activemodel-6.0.0.rc2/lib/active_model/serialization.rb:137:in `serializable_hash'
    /Users/jon/.asdf/installs/ruby/2.6.3/lib/ruby/gems/2.6.0/gems/activerecord-6.0.0.rc2/lib/active_record/serialization.rb:19:in `serializable_hash'
    /Users/jon/.asdf/installs/ruby/2.6.3/lib/ruby/gems/2.6.0/gems/devise-4.6.2/lib/devise/models/authenticatable.rb:116:in `serializable_hash'
    /Users/jon/.asdf/installs/ruby/2.6.3/lib/ruby/gems/2.6.0/gems/devise-4.6.2/lib/devise/models/authenticatable.rb:122:in `inspect'
    /Users/jon/.asdf/installs/ruby/2.6.3/lib/ruby/gems/2.6.0/gems/activejob-6.0.0.rc2/lib/active_job/test_helper.rb:408:in `inspect'
    /Users/jon/.asdf/installs/ruby/2.6.3/lib/ruby/gems/2.6.0/gems/activejob-6.0.0.rc2/lib/active_job/test_helper.rb:408:in `inspect'
    /Users/jon/.asdf/installs/ruby/2.6.3/lib/ruby/gems/2.6.0/gems/activejob-6.0.0.rc2/lib/active_job/test_helper.rb:408:in `inspect'
    /Users/jon/.asdf/installs/ruby/2.6.3/lib/ruby/gems/2.6.0/gems/activejob-6.0.0.rc2/lib/active_job/test_helper.rb:408:in `inspect'
    /Users/jon/.asdf/installs/ruby/2.6.3/lib/ruby/gems/2.6.0/gems/activejob-6.0.0.rc2/lib/active_job/test_helper.rb:408:in `assert_enqueued_with'
    /Users/jon/.asdf/installs/ruby/2.6.3/lib/ruby/gems/2.6.0/gems/actionmailer-6.0.0.rc2/lib/action_mailer/test_helper.rb:132:in `assert_enqueued_email_with'
    /Users/jon/Projects/project_name/test/models/user_test.rb:639:in `block in <class:UserTest>'

The test is:

test 'will enqueue email to admins if new user has role of "admin"' do
  user = User.new(
    email: 'new+user@example.com',
    password: 'abc123!',
    first_name: 'account_team',
    last_name: 'test',
    role: 'admin'
  )

  assert_enqueued_email_with AdminNotificationsMailer, :new_admin_user, args: [user] do
    user.save!
  end
end

I can try to find more examples if you'd like.

[palkan]

Thanks! I think, that should be enough.

Pushed one more fix for this use-case: removed exception, reverted to returning nil if log_data is not loaded—it seems there is no way to distinguish between ignored log_data and a new record's nil (that's the example above).

[jonknapp]

It works! 🎉 All tests are passing with latest master: 7d5c33e

Awesome job!