portagenetwork / roadmap

Developed by the the Alliance in collaboration with University of Alberta, DMP Assistant a data management planning tool, forking the DMP Roadmap codebase
MIT License
6 stars 1 forks source link

ActiveRecord::RecordInvalid: Validation failed: Question must be unique #789

Closed aaronskiba closed 1 week ago

aaronskiba commented 3 weeks ago

View details in Rollbar: https://app.rollbar.com/a/ualbertalib/fix/item/dmp_assistant/467



ActiveRecord::RecordInvalid: Validation failed: Question must be unique
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activerecord-6.1.7.6/lib/active_record/validations.rb", line 80, in raise_validation_error
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activerecord-6.1.7.6/lib/active_record/validations.rb", line 53, in save!
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activerecord-6.1.7.6/lib/active_record/transactions.rb", line 302, in block in save!
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activerecord-6.1.7.6/lib/active_record/transactions.rb", line 354, in block in with_transaction_returning_status
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activerecord-6.1.7.6/lib/active_record/connection_adapters/abstract/database_statements.rb", line 320, in block in transaction
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activerecord-6.1.7.6/lib/active_record/connection_adapters/abstract/transaction.rb", line 319, in block in within_new_transaction
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/concurrency/load_interlock_aware_monitor.rb", line 26, in block (2 levels) in synchronize
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/concurrency/load_interlock_aware_monitor.rb", line 25, in handle_interrupt
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/concurrency/load_interlock_aware_monitor.rb", line 25, in block in synchronize
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/concurrency/load_interlock_aware_monitor.rb", line 21, in handle_interrupt
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/concurrency/load_interlock_aware_monitor.rb", line 21, in synchronize
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activerecord-6.1.7.6/lib/active_record/connection_adapters/abstract/transaction.rb", line 317, in within_new_transaction
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activerecord-6.1.7.6/lib/active_record/connection_adapters/abstract/database_statements.rb", line 320, in transaction
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activerecord-6.1.7.6/lib/active_record/transactions.rb", line 350, in with_transaction_returning_status
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activerecord-6.1.7.6/lib/active_record/transactions.rb", line 302, in save!
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activerecord-6.1.7.6/lib/active_record/suppressor.rb", line 48, in save!
  File "/var/www/sites/dmp/app/models/plan.rb", line 258, in block in deep_copy
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activerecord-6.1.7.6/lib/active_record/relation/delegation.rb", line 88, in each
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activerecord-6.1.7.6/lib/active_record/relation/delegation.rb", line 88, in each
  File "/var/www/sites/dmp/app/models/plan.rb", line 255, in deep_copy
  File "/var/www/sites/dmp/app/controllers/plans_controller.rb", line 390, in duplicate
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/action_controller/metal/basic_implicit_render.rb", line 6, in send_action
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/abstract_controller/base.rb", line 228, in process_action
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/action_controller/metal/rendering.rb", line 30, in process_action
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/abstract_controller/callbacks.rb", line 42, in block in process_action
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/callbacks.rb", line 117, in block in run_callbacks
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actiontext-6.1.7.6/lib/action_text/rendering.rb", line 20, in with_renderer
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actiontext-6.1.7.6/lib/action_text/engine.rb", line 59, in block (4 levels) in <class:Engine>
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/callbacks.rb", line 126, in instance_exec
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/callbacks.rb", line 126, in block in run_callbacks
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/callbacks.rb", line 137, in run_callbacks
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/abstract_controller/callbacks.rb", line 41, in process_action
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/action_controller/metal/rescue.rb", line 22, in process_action
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/action_controller/metal/instrumentation.rb", line 34, in block in process_action
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/notifications.rb", line 203, in block in instrument
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/notifications/instrumenter.rb", line 24, in instrument
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/notifications.rb", line 203, in instrument
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/action_controller/metal/instrumentation.rb", line 33, in process_action
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/action_controller/metal/params_wrapper.rb", line 249, in process_action
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/activerecord-6.1.7.6/lib/active_record/railties/controller_runtime.rb", line 27, in process_action
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/abstract_controller/base.rb", line 165, in process
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionview-6.1.7.6/lib/action_view/rendering.rb", line 39, in process
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/action_controller/metal.rb", line 190, in dispatch
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/action_controller/metal.rb", line 254, in dispatch
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/action_dispatch/routing/route_set.rb", line 50, in dispatch
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/action_dispatch/routing/route_set.rb", line 33, in serve
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/action_dispatch/journey/router.rb", line 50, in block in serve
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib/action_dispatch/journey/router.rb", line 32, in each
  File "/var/www/sites/dmp/vendor/ruby/2.7.0/gems/actionpack-6.1.7.6/lib
aaronskiba commented 3 weeks ago

This appears to be an occurrence of the following issue: https://github.com/portagenetwork/roadmap/issues/593

SELECT question_id, COUNT(question_id)
FROM answers
WHERE plan_id = 13558
GROUP BY question_id
HAVING COUNT(question_id) > 1
question_id count
72638 2

Screenshot from 2024-06-06 16-37-00

aaronskiba commented 3 weeks ago

The corresponding Plan.section shows that (5/4) questions have been answered. Screenshot from 2024-06-07 13-54-17

aaronskiba commented 3 weeks ago

In addition to the "copy" functionality not working, the duplicate answer cannot be updated either:

Screenshot from 2024-06-07 13-53-21

[51, 60] in /home/aaron/Documents/GitHub/roadmap/app/controllers/answers_controller.rb
   51:         question_id: args[:question_id]
   52:       )
   53:       authorize @answer
   54: 
   55:       byebug
=> 56:       @answer.update(args.merge(user_id: current_user.id))
   57:       if args[:question_option_ids].present?
   58:         # Saves the record with the updated_at set to the current time.
   59:         # Needed if only answer.question_options is updated
   60:         @answer.touch
(byebug) @answer.update!(args.merge(user_id: current_user.id))
  QuestionOption Load (1.4ms)  SELECT "question_options".* FROM "question_options" INNER JOIN "answers_question_options" ON "question_options"."id" = "answers_question_options"."question_option_id" WHERE "answers_question_options"."answer_id" = $1  [["answer_id", 67389]]
  ↳ (byebug):1:in `block in create_or_update'
  Question Load (1.0ms)  SELECT "questions".* FROM "questions" WHERE "questions"."id" = $1 ORDER BY "questions"."number" ASC LIMIT $2  [["id", 72638], ["LIMIT", 1]]
  ↳ (byebug):1:in `block in create_or_update'
  User Load (1.5ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT $2  [["id", 25743], ["LIMIT", 1]]
  ↳ (byebug):1:in `block in create_or_update'
  Answer Exists? (1.5ms)  SELECT 1 AS one FROM "answers" WHERE "answers"."question_id" = $1 AND "answers"."id" != $2 AND "answers"."plan_id" = $3 LIMIT $4  [["question_id", 72638], ["id", 67389], ["plan_id", 13558], ["LIMIT", 1]]
  ↳ (byebug):1:in `block in create_or_update'
*** ActiveRecord::RecordInvalid Exception: Validation failed: Question must be unique
aaronskiba commented 3 weeks ago
SELECT COUNT(id) 
FROM answers;
---------------------------
67327

*************************************************************

SELECT COUNT(*)
FROM answers
JOIN (
    SELECT plan_id, question_id
    FROM answers
    GROUP BY plan_id, question_id
    HAVING COUNT(*) > 1
) AS duplicates
ON answers.plan_id = duplicates.plan_id AND answers.question_id = duplicates.question_id;
----------------------------
22

According to these queries, there are 11 (22/2) answers with "duplicates" in the answers table. So only 0.00016% (11/67327) of the answers entries are affected.

aaronskiba commented 3 weeks ago

This table illustrates how close the created_at values are between the answers and their duplicates (max = 0.014105 seconds).

id duplicate_id plan_id question_id created_at duplicate_created_at time_difference_seconds
26035 26036 6914 67418 2021-04-02 19:54:36 2021-04-02 19:54:36 0
34772 34773 8424 68834 2021-12-17 23:01:46 2021-12-17 23:01:46 0
41114 41115 9347 69714 2022-06-04 02:52:42 2022-06-04 02:52:42 0
41124 41125 9347 69723 2022-06-04 04:46:48 2022-06-04 04:46:48 0
49172 49173 10912 68316 2023-03-22 15:26:56.835211 2023-03-22 15:26:56.842863 0.007652
49711 49712 11005 74820 2023-04-03 07:10:32.197305 2023-04-03 07:10:32.205013 0.007708
52035 52036 11366 68127 2023-05-23 19:21:09.952598 2023-05-23 19:21:09.964106 0.011508
54484 54485 11785 72244 2023-08-21 14:01:49.753142 2023-08-21 14:01:49.767247 0.014105
55605 55606 12007 69720 2023-09-20 00:20:59.242693 2023-09-20 00:20:59.24843 0.005737
60793 60794 12632 75680 2023-11-27 03:02:59.964372 2023-11-27 03:02:59.970709 0.006337
67389 67390 13558 72638 2024-05-08 23:18:26.696402 2024-05-08 23:18:26.700717 0.004315
aaronskiba commented 3 weeks ago

We can see there is a very small percentage of duplicates, and the created_at difference is very small between the answers and their corresponding duplicates. Given all of this, it seems quite possible that we're sometimes encountering a race condition which causes the question uniqueness validation check to sometimes fail. When two records are being saved nearly simultaneously, the validation check might pass for both before either is committed to the database, leading to the insertion of duplicate entries.

This seems even more likely when we factor in the 'auto-save' feature being used for answers. If a manually save was executed and an auto-save was triggered at nearly the same moment, then the aforementioned scenario could occur.

Perhaps a migration should be created to enforce the uniqueness constraint at the db level?

aaronskiba commented 1 week ago

Closing this issue as it is a symptom that will be remedied after addressing issue https://github.com/portagenetwork/roadmap/issues/800.