mysociety / ipvtheme

The Alaveteli theme for Informace pro vsechny (Czech Republic)
http://infoprovsechny.cz
MIT License
3 stars 4 forks source link

[ERROR] script/update-overdue-info-request-events (ActiveRecord::StatementInvalid: PG::CardinalityViolation) #44

Closed garethrees closed 3 years ago

garethrees commented 3 years ago
rake aborted!
ActiveRecord::StatementInvalid: PG::CardinalityViolation: ERROR: more than one row returned by a subquery used as an expression
: SELECT "info_requests".* FROM "info_requests" WHERE (awaiting_description = FALSE
AND described_state = 'waiting_response'
AND date_very_overdue_after < '2020-09-21'
AND (SELECT id
FROM info_request_events
WHERE info_request_id = info_requests.id
AND event_type = 'very_overdue'
AND created_at > info_requests.date_very_overdue_after)
IS NULL) ORDER BY "info_requests"."id" ASC LIMIT $1
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `exec_params'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `block (2 levels) in exec_no_cache'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:610:in `block in exec_no_cache'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract_adapter.rb:581:in `block (2 levels) in log'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract_adapter.rb:580:in `block in log'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract_adapter.rb:571:in `log'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:609:in `exec_no_cache'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:598:in `execute_and_clear'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql/database_statements.rb:81:in `exec_query'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:478:in `select'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:70:in `select_all'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/query_cache.rb:106:in `select_all'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/querying.rb:41:in `find_by_sql'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:560:in `block in exec_queries'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:581:in `block in skip_query_cache_if_necessary'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/query_cache.rb:78:in `uncached'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/query_cache.rb:21:in `uncached'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation/delegation.rb:97:in `block in uncached'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:281:in `scoping'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation/delegation.rb:97:in `uncached'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:580:in `skip_query_cache_if_necessary'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:547:in `exec_queries'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:422:in `load'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:200:in `records'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation/batches.rb:224:in `block in in_batches'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation/batches.rb:222:in `loop'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation/batches.rb:222:in `in_batches'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation/batches.rb:135:in `find_in_batches'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation/batches.rb:69:in `find_each'
/data/vhost/czechia.alaveteli.org/alaveteli-2020-09-17T13-52-10/app/models/info_request.rb:683:in `log_overdue_event_type'
/data/vhost/czechia.alaveteli.org/alaveteli-2020-09-17T13-52-10/app/models/info_request.rb:655:in `log_very_overdue_events'
/data/vhost/czechia.alaveteli.org/alaveteli-2020-09-17T13-52-10/lib/tasks/stats.rake:263:in `block (2 levels) in <top (required)>'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/rake-13.0.1/exe/rake:27:in `<top (required)>'
/opt/rbenv/versions/2.6.6/bin/bundle:23:in `load'
/opt/rbenv/versions/2.6.6/bin/bundle:23:in `<main>'

Caused by:
PG::CardinalityViolation: ERROR: more than one row returned by a subquery used as an expression
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `exec_params'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `block (2 levels) in exec_no_cache'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:610:in `block in exec_no_cache'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract_adapter.rb:581:in `block (2 levels) in log'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract_adapter.rb:580:in `block in log'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract_adapter.rb:571:in `log'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:609:in `exec_no_cache'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:598:in `execute_and_clear'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql/database_statements.rb:81:in `exec_query'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:478:in `select'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:70:in `select_all'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/query_cache.rb:106:in `select_all'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/querying.rb:41:in `find_by_sql'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:560:in `block in exec_queries'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:581:in `block in skip_query_cache_if_necessary'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/query_cache.rb:78:in `uncached'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/query_cache.rb:21:in `uncached'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation/delegation.rb:97:in `block in uncached'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:281:in `scoping'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation/delegation.rb:97:in `uncached'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:580:in `skip_query_cache_if_necessary'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:547:in `exec_queries'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:422:in `load'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:200:in `records'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation/batches.rb:224:in `block in in_batches'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation/batches.rb:222:in `loop'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation/batches.rb:222:in `in_batches'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation/batches.rb:135:in `find_in_batches'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/relation/batches.rb:69:in `find_each'
/data/vhost/czechia.alaveteli.org/alaveteli-2020-09-17T13-52-10/app/models/info_request.rb:683:in `log_overdue_event_type'
/data/vhost/czechia.alaveteli.org/alaveteli-2020-09-17T13-52-10/app/models/info_request.rb:655:in `log_very_overdue_events'
/data/vhost/czechia.alaveteli.org/alaveteli-2020-09-17T13-52-10/lib/tasks/stats.rake:263:in `block (2 levels) in <top (required)>'
/data/vhost/czechia.alaveteli.org/shared/vendor/bundle/ruby/2.6.0/gems/rake-13.0.1/exe/rake:27:in `<top (required)>'
/opt/rbenv/versions/2.6.6/bin/bundle:23:in `load'
/opt/rbenv/versions/2.6.6/bin/bundle:23:in `<main>'
Tasks: TOP => stats:update_overdue_info_request_events
(See full trace by running task with --trace)
stalled?
gbp commented 3 years ago

This is due to some requests having more than one very_overdue InfoRequestEvent:

=> SELECT info_request_id, COUNT(*) FROM info_request_events WHERE event_type = 'very_overdue' GROUP BY info_request_id;

 info_request_id | count
-----------------+-------
            2848 |     2
...

It appears before 2017-04-21, these events were duplicated - with exact same created_at/updated_at timestamps. So we could delete duplicated events or something like this should work:

diff --git a/app/models/info_request.rb b/app/models/info_request.rb
index c3494e7246..c574c37109 100644
--- a/app/models/info_request.rb
+++ b/app/models/info_request.rb
@@ -673,7 +673,8 @@ class InfoRequest < ApplicationRecord
               FROM info_request_events
               WHERE info_request_id = info_requests.id
               AND event_type = ?
-              AND created_at > info_requests.#{date_field})
+              AND created_at > info_requests.#{date_field}
+              LIMIT 1)
               IS NULL",
               false,
               'waiting_response',
gbp commented 3 years ago

This shows the duplciated records:

SELECT ire1.id, ire2.id, ire1.info_request_id, ire1.created_at, ire2.created_at, ire1.updated_at, ire2.updated_at
FROM info_request_events ire1
INNER JOIN info_request_events ire2 ON (
  ire1.event_type = ire2.event_type AND
  ire1.id < ire2.id AND
  ire1.info_request_id = ire2.info_request_id
)
WHERE ire1.event_type = 'very_overdue';
garethrees commented 3 years ago

I haven't dug into this, but I don't see why a request shouldn't be able to have 2 very_overdue events. We account for clarification requests (which reset the clock), so the chain of events could plausibly be:

  1. Awaiting response
  2. Overdue
  3. Very overdue
  4. Response comes in – asks to clarify
  5. Followup sent – clock reset
  6. Overdue
  7. Very overdue

I don't know why we'd get 2 with an identical timestamp though. The SQL snippet gives a syntax error.

gbp commented 3 years ago

The SQL snippet gives a syntax error.

Stray comma - fixed

gbp commented 3 years ago

Oh I wonder if this is caused by running bundle exec rake temp:backload_very_overdue_info_request_events twice

garethrees commented 3 years ago

Oh I wonder if this is caused by running bundle exec rake temp:backload_very_overdue_info_request_events twice

Sounds probable – should be able to test locally?

gbp commented 3 years ago

Couldn't replicate the issue locally. Instead I've used the rails console to remvoe duplciate InfoRequestEvent records where all the attributes (excpet ID of course) match and have deleted.

Script now runs without erroring.