`responsible_id` is not updated on relation with `touch: true`

[adas172002]

Hi,

I noticed that current Logidze is not storing m => {_r} on models updated by belongs_to :some_model, touch: true option. Logidze history object looks like this:

@data=
     {"c"=>{"updated_at"=>"2023-04-10 17:54:45.78185"},
      "v"=>5,
      "ts"=>1681149285782}

responsible_id on related model is stored correctly.

This is not related to old SQL db triggers code - I started to use logidze in my project with version 1.2.3.

[palkan]

Interesting. Could you please provide a bit more details? How do you define the responsible, how do you update records?

[adas172002]

Models relation is 2 levels deep: Production class has_one :decision, which in turn has_many :capas, both with touch: true. I am using accepts_nested_attributes_for in both Decision and CAPA in order to be able to edit related decision and capas in one form. ProductionsController#update includes Logidze.with_responsible(current_user.id){@production.update(production_params)}, which works as expected when there are any changes in the Production instance. But in case there are no changes to production instance itself, update action is not storing _r, which is not what I expect - by touching parent model I am updating updated_at timestamp every time. Updated_at is stored in logidze history hash, but m => {_r} tree is missing for production. Updated production child models do have metadata hash (only if there are changes in their respected instances, though).

Thanks for your help on the matter.

[palkan]

Thanks!

I have no ideas so far. The metadata is set for the whole block in the very beginning and used by all triggers.

One suggestion is to try log SQL queries and see what't happening under the hood.

Can you please drop the following line of code right before Logidze.with_responsible and provide logs for both cases:

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

?

[adas172002]

Hi @palkan

Here's the log for update action when Production instance child CAPA instance date attribute is changed ONLY:

D, [2023-04-13T21:08:32.214082 #82826] DEBUG -- :   TRANSACTION (0.1ms)  BEGIN
D, [2023-04-13T21:08:32.214393 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block in update'
D, [2023-04-13T21:08:32.214600 #82826] DEBUG -- :    (0.2ms)  SET LOCAL logidze.meta = '{"_r":37}';
D, [2023-04-13T21:08:32.214813 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block in update'
D, [2023-04-13T21:08:32.216382 #82826] DEBUG -- :   Nonconformity Load (0.1ms)  SELECT "nonconformities".* FROM "nonconformities" WHERE "nonconformities"."reportable_id" = $1 AND "nonconformities"."reportable_type" = $2 LIMIT $3  [["reportable_id", 4], ["reportable_type", "Production"], ["LIMIT", 1]]
D, [2023-04-13T21:08:32.216742 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:08:32.217465 #82826] DEBUG -- :   Decision Load (0.1ms)  SELECT "decisions".* FROM "decisions" WHERE "decisions"."production_id" = $1 LIMIT $2  [["production_id", 4], ["LIMIT", 1]]
D, [2023-04-13T21:08:32.217830 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:08:32.218711 #82826] DEBUG -- :   CAPA Load (0.2ms)  SELECT "capas".* FROM "capas" WHERE "capas"."decision_id" = $1 AND "capas"."id" IN ($2, $3)  [["decision_id", 4], ["id", 5], ["id", 6]]
D, [2023-04-13T21:08:32.219095 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:08:32.219983 #82826] DEBUG -- :   Identification Load (0.1ms)  SELECT "identifications".* FROM "identifications" WHERE "identifications"."production_id" = $1 AND "identifications"."id" IN ($2, $3)  [["production_id", 4], ["id", 4], ["id", 5]]
D, [2023-04-13T21:08:32.220317 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:08:32.221044 #82826] DEBUG -- :   WorkOrder Load (0.1ms)  SELECT "work_orders".* FROM "work_orders" WHERE "work_orders"."nbr" = $1 LIMIT $2  [["nbr", "4499563_01"], ["LIMIT", 1]]
D, [2023-04-13T21:08:32.221283 #82826] DEBUG -- :   ↳ app/models/production.rb:25:in `block in work_orders_attributes='
D, [2023-04-13T21:08:32.222042 #82826] DEBUG -- :   WorkOrder Load (0.2ms)  SELECT "work_orders".* FROM "work_orders" INNER JOIN "jobs" ON "work_orders"."id" = "jobs"."work_order_id" WHERE "jobs"."production_id" = $1  [["production_id", 4]]
D, [2023-04-13T21:08:32.222321 #82826] DEBUG -- :   ↳ app/models/production.rb:28:in `work_orders_attributes='
D, [2023-04-13T21:08:32.223533 #82826] DEBUG -- :   CACHE User Load (0.0ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" DESC LIMIT $2  [["id", 37], ["LIMIT", 1]]
D, [2023-04-13T21:08:32.223998 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:08:32.225046 #82826] DEBUG -- :   Activity Load (0.1ms)  SELECT "activities".* FROM "activities" WHERE "activities"."id" = $1 ORDER BY "activities"."id" ASC LIMIT $2  [["id", 3], ["LIMIT", 1]]
D, [2023-04-13T21:08:32.225532 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:08:32.226501 #82826] DEBUG -- :   Reject Load (0.1ms)  SELECT "rejects".* FROM "rejects" WHERE "rejects"."id" = $1 ORDER BY "rejects"."id" ASC LIMIT $2  [["id", 7], ["LIMIT", 1]]
D, [2023-04-13T21:08:32.226985 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:08:32.228029 #82826] DEBUG -- :   Task Load (0.1ms)  SELECT "tasks".* FROM "tasks" WHERE "tasks"."id" = $1 ORDER BY "tasks"."id" ASC LIMIT $2  [["id", 9], ["LIMIT", 1]]
D, [2023-04-13T21:08:32.228525 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:08:32.229905 #82826] DEBUG -- :   User Load (0.1ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" DESC LIMIT $2  [["id", 26], ["LIMIT", 1]]
D, [2023-04-13T21:08:32.230619 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:08:32.237555 #82826] DEBUG -- :   CAPA Update (4.5ms)  UPDATE "capas" SET "date" = $1 WHERE "capas"."id" = $2  [["date", "2023-04-27"], ["id", 6]]
D, [2023-04-13T21:08:32.238160 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:08:32.238833 #82826] DEBUG -- :    (0.1ms)  SET LOCAL logidze.meta TO DEFAULT;
D, [2023-04-13T21:08:32.239098 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block in update'
D, [2023-04-13T21:08:32.240971 #82826] DEBUG -- :   Production Update (1.5ms)  UPDATE "productions" SET "updated_at" = $1 WHERE "productions"."id" = $2  [["updated_at", "2023-04-13 19:08:32.238573"], ["id", 4]]
D, [2023-04-13T21:08:32.241331 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block in update'
D, [2023-04-13T21:08:32.241969 #82826] DEBUG -- :   TRANSACTION (0.5ms)  COMMIT

Log for a use case when Production instance attribute is changed as well

D, [2023-04-13T21:16:15.913142 #82826] DEBUG -- :   TRANSACTION (0.1ms)  BEGIN
D, [2023-04-13T21:16:15.913570 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block in update'
D, [2023-04-13T21:16:15.913872 #82826] DEBUG -- :    (0.2ms)  SET LOCAL logidze.meta = '{"_r":37}';
D, [2023-04-13T21:16:15.914203 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block in update'
D, [2023-04-13T21:16:15.916658 #82826] DEBUG -- :   Nonconformity Load (0.2ms)  SELECT "nonconformities".* FROM "nonconformities" WHERE "nonconformities"."reportable_id" = $1 AND "nonconformities"."reportable_type" = $2 LIMIT $3  [["reportable_id", 4], ["reportable_type", "Production"], ["LIMIT", 1]]
D, [2023-04-13T21:16:15.917199 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:16:15.918229 #82826] DEBUG -- :   Decision Load (0.2ms)  SELECT "decisions".* FROM "decisions" WHERE "decisions"."production_id" = $1 LIMIT $2  [["production_id", 4], ["LIMIT", 1]]
D, [2023-04-13T21:16:15.918751 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:16:15.919995 #82826] DEBUG -- :   CAPA Load (0.3ms)  SELECT "capas".* FROM "capas" WHERE "capas"."decision_id" = $1 AND "capas"."id" IN ($2, $3)  [["decision_id", 4], ["id", 5], ["id", 6]]
D, [2023-04-13T21:16:15.920587 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:16:15.921841 #82826] DEBUG -- :   Identification Load (0.2ms)  SELECT "identifications".* FROM "identifications" WHERE "identifications"."production_id" = $1 AND "identifications"."id" IN ($2, $3)  [["production_id", 4], ["id", 4], ["id", 5]]
D, [2023-04-13T21:16:15.922314 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:16:15.923085 #82826] DEBUG -- :   WorkOrder Load (0.1ms)  SELECT "work_orders".* FROM "work_orders" WHERE "work_orders"."nbr" = $1 LIMIT $2  [["nbr", "4499563_01"], ["LIMIT", 1]]
D, [2023-04-13T21:16:15.923379 #82826] DEBUG -- :   ↳ app/models/production.rb:25:in `block in work_orders_attributes='
D, [2023-04-13T21:16:15.924390 #82826] DEBUG -- :   WorkOrder Load (0.3ms)  SELECT "work_orders".* FROM "work_orders" INNER JOIN "jobs" ON "work_orders"."id" = "jobs"."work_order_id" WHERE "jobs"."production_id" = $1  [["production_id", 4]]
D, [2023-04-13T21:16:15.924776 #82826] DEBUG -- :   ↳ app/models/production.rb:28:in `work_orders_attributes='
D, [2023-04-13T21:16:15.925854 #82826] DEBUG -- :   CACHE User Load (0.0ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" DESC LIMIT $2  [["id", 37], ["LIMIT", 1]]
D, [2023-04-13T21:16:15.926417 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:16:15.927656 #82826] DEBUG -- :   Activity Load (0.2ms)  SELECT "activities".* FROM "activities" WHERE "activities"."id" = $1 ORDER BY "activities"."id" ASC LIMIT $2  [["id", 3], ["LIMIT", 1]]
D, [2023-04-13T21:16:15.928205 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:16:15.929109 #82826] DEBUG -- :   Reject Load (0.2ms)  SELECT "rejects".* FROM "rejects" WHERE "rejects"."id" = $1 ORDER BY "rejects"."id" ASC LIMIT $2  [["id", 7], ["LIMIT", 1]]
D, [2023-04-13T21:16:15.929627 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:16:15.930525 #82826] DEBUG -- :   Task Load (0.1ms)  SELECT "tasks".* FROM "tasks" WHERE "tasks"."id" = $1 ORDER BY "tasks"."id" ASC LIMIT $2  [["id", 9], ["LIMIT", 1]]
D, [2023-04-13T21:16:15.931039 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:16:15.937948 #82826] DEBUG -- :   Production Update (5.9ms)  UPDATE "productions" SET "updated_at" = $1, "qty_detected" = $2 WHERE "productions"."id" = $3  [["updated_at", "2023-04-13 19:16:15.931545"], ["qty_detected", "7"], ["id", 4]]
D, [2023-04-13T21:16:15.938326 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block (2 levels) in update'
D, [2023-04-13T21:16:15.939160 #82826] DEBUG -- :    (0.1ms)  SET LOCAL logidze.meta TO DEFAULT;
D, [2023-04-13T21:16:15.939402 #82826] DEBUG -- :   ↳ app/controllers/productions_controller.rb:59:in `block in update'
D, [2023-04-13T21:16:15.939956 #82826] DEBUG -- :   TRANSACTION (0.5ms)  COMMIT

I am not sure if this will help to investigate my issue. In both cases meta is correctly set to m => { "_r" => 37}, which is current_user.id value. Perhaps this is a postgresql issue? I am on version 12.4 BTW.

[palkan]

Thanks for the logs. We can see that in the first case meta rollback (SET LOCAL logidze.meta TO DEFAULT;) happens right before the touch: true triggered UPDATE (and right after the first UPDATE).

I will try to reproduce it in tests.

[palkan]

I will try to reproduce it in tests.

Ok, it took me quite a time but I finally figured this out. See https://github.com/palkan/logidze/commit/caf7d9042d34bc1a4e289b3c4e32d6595646df5a

tl;dr touch: true callbacks are executed after commits; since with_meta wraps the execution into a transaction by default, changes made outside of it doesn't include the meta information. Solution? Use with_meta(x, transactional: false) (as in the test) if possible.