Geo: Log cursor fails to reconnect after being disconnected
I noticed this on the GPRD site:
This is likely related to gitlab-com/migration#242 (closed), which caused PostgreSQL to crash:
2018-03-06_13:09:23.08482 web-01-sv-gprd geo-logcursor: /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql_adapter.rb:651:in `initialize': ERROR: pgbouncer cannot connect to server (PG::ConnectionBad)
2018-03-06_13:09:23.08488 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql_adapter.rb:651:in `new'
2018-03-06_13:09:23.08490 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql_adapter.rb:651:in `connect'
2018-03-06_13:09:23.08491 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql_adapter.rb:242:in `initialize'
2018-03-06_13:09:23.08492 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql_adapter.rb:44:in `new'
2018-03-06_13:09:23.08493 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql_adapter.rb:44:in `postgresql_connection'
2018-03-06_13:09:23.08494 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract/connection_pool.rb:438:in `new_connection'
2018-03-06_13:09:23.08495 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract/connection_pool.rb:448:in `checkout_new_connection'
2018-03-06_13:09:23.08496 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract/connection_pool.rb:422:in `acquire_connection'
2018-03-06_13:09:23.08498 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract/connection_pool.rb:349:in `block in checkout'
2018-03-06_13:09:23.08499 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
2018-03-06_13:09:23.08500 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract/connection_pool.rb:348:in `checkout'
2018-03-06_13:09:23.08501 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract/connection_pool.rb:263:in `block in connection'
2018-03-06_13:09:23.08502 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
2018-03-06_13:09:23.08503 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract/connection_pool.rb:262:in `connection'
2018-03-06_13:09:23.08504 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract/connection_pool.rb:571:in `retrieve_connection'
2018-03-06_13:09:23.08505 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_handling.rb:113:in `retrieve_connection'
2018-03-06_13:09:23.08506 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/connection_handling.rb:87:in `connection'
2018-03-06_13:09:23.08507 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.10/lib/active_record/model_schema.rb:230:in `table_exists?'
2018-03-06_13:09:23.08509 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/service/gitlab-rails/app/models/concerns/sha_attribute.rb:7:in `sha_attribute'
2018-03-06_13:09:23.08510 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/service/gitlab-rails/app/models/gpg_key.rb:7:in `<class:GpgKey>'
2018-03-06_13:09:23.08511 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/service/gitlab-rails/app/models/gpg_key.rb:1:in `<top (required)>'
2018-03-06_13:09:23.08512 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activesupport-4.2.10/lib/active_support/dependencies.rb:274:in `require'
2018-03-06_13:09:23.08513 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activesupport-4.2.10/lib/active_support/dependencies.rb:274:in `block in require'
2018-03-06_13:09:23.08514 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activesupport-4.2.10/lib/active_support/dependencies.rb:240:in `load_dependency'
2018-03-06_13:09:23.08515 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activesupport-4.2.10/lib/active_support/dependencies.rb:274:in `require'
2018-03-06_13:09:23.08516 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activesupport-4.2.10/lib/active_support/dependencies.rb:360:in `require_or_load'
2018-03-06_13:09:23.08517 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activesupport-4.2.10/lib/active_support/dependencies.rb:317:in `depend_on'
2018-03-06_13:09:23.08518 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activesupport-4.2.10/lib/active_support/dependencies.rb:233:in `require_dependency'
2018-03-06_13:09:23.08519 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.10/lib/rails/engine.rb:472:in `block (2 levels) in eager_load!'
2018-03-06_13:09:23.08520 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.10/lib/rails/engine.rb:471:in `each'
2018-03-06_13:09:23.08522 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.10/lib/rails/engine.rb:471:in `block in eager_load!'
2018-03-06_13:09:23.08523 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.10/lib/rails/engine.rb:469:in `each'
2018-03-06_13:09:23.08524 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.10/lib/rails/engine.rb:469:in `eager_load!'
2018-03-06_13:09:23.08525 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.10/lib/rails/engine.rb:346:in `eager_load!'
2018-03-06_13:09:23.08526 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.10/lib/rails/application/finisher.rb:56:in `each'
2018-03-06_13:09:23.08527 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.10/lib/rails/application/finisher.rb:56:in `block in <module:Finisher>'
2018-03-06_13:09:23.08528 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.10/lib/rails/initializable.rb:30:in `instance_exec'
2018-03-06_13:09:23.08529 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.10/lib/rails/initializable.rb:30:in `run'
2018-03-06_13:09:23.08530 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.10/lib/rails/initializable.rb:55:in `block in run_initializers'
2018-03-06_13:09:23.08531 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/2.3.0/tsort.rb:228:in `block in tsort_each'
2018-03-06_13:09:23.08532 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/2.3.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
2018-03-06_13:09:23.08533 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/2.3.0/tsort.rb:431:in `each_strongly_connected_component_from'
2018-03-06_13:09:23.08534 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/2.3.0/tsort.rb:349:in `block in each_strongly_connected_component'
2018-03-06_13:09:23.08535 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/2.3.0/tsort.rb:347:in `each'
2018-03-06_13:09:23.08536 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/2.3.0/tsort.rb:347:in `call'
2018-03-06_13:09:23.08537 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/2.3.0/tsort.rb:347:in `each_strongly_connected_component'
2018-03-06_13:09:23.08538 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/2.3.0/tsort.rb:226:in `tsort_each'
2018-03-06_13:09:23.08539 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/2.3.0/tsort.rb:205:in `tsort_each'
2018-03-06_13:09:23.08540 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.10/lib/rails/initializable.rb:54:in `run_initializers'
2018-03-06_13:09:23.08541 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.10/lib/rails/application.rb:352:in `initialize!'
2018-03-06_13:09:23.08542 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/service/gitlab-rails/config/environment.rb:5:in `<top (required)>'
2018-03-06_13:09:23.08543 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/service/gitlab-rails/bin/geo_log_cursor:42:in `require'
2018-03-06_13:09:23.08544 web-01-sv-gprd geo-logcursor: from /opt/gitlab/embedded/service/gitlab-rails/bin/geo_log_cursor:42:in `<main>'
2018-03-06_15:50:15.59627 web-01-sv-gprd geo-logcursor: FATAL: terminating connection due to idle-in-transaction timeoutHowever, in the Geo log, I see these errors:
{"severity":"ERROR","time":"2018-03-06T18:24:21.996Z","pid":418,"class":"Lease","message":"Lease canceled due to error: PG::ConnectionBad: PQsocket() can't get socket descriptor: SELECT \"event_log_states\".* FROM \"event_log_states\" ORDER BY \"event_log_states\".\"event_id\" DESC LIMIT 1"}
{"severity":"ERROR","time":"2018-03-06T18:24:52.602Z","pid":418,"class":"Lease","message":"Lease canceled due to error: PG::ConnectionBad: PQsocket() can't get socket descriptor: SELECT \"event_log_states\".* FROM \"event_log_states\" ORDER BY \"event_log_states\".\"event_id\" DESC LIMIT 1"}
{"severity":"ERROR","time":"2018-03-06T18:25:23.608Z","pid":418,"class":"Lease","message":"Lease canceled due to error: PG::ConnectionBad: PQsocket() can't get socket descriptor: SELECT \"event_log_states\".* FROM \"event_log_states\" ORDER BY \"event_log_states\".\"event_id\" DESC LIMIT 1"}
{"severity":"ERROR","time":"2018-03-06T18:25:54.721Z","pid":418,"class":"Lease","message":"Lease canceled due to error: PG::ConnectionBad: PQsocket() can't get socket descriptor: SELECT \"event_log_states\".* FROM \"event_log_states\" ORDER BY \"event_log_states\".\"event_id\" DESC LIMIT 1"}
{"severity":"ERROR","time":"2018-03-06T18:26:25.928Z","pid":418,"class":"Lease","message":"Lease canceled due to error: PG::ConnectionBad: PQsocket() can't get socket descriptor: SELECT \"event_log_states\".* FROM \"event_log_states\" ORDER BY \"event_log_states\".\"event_id\" DESC LIMIT 1"}I verified the DB is back up, but some reason Rails didn't reconnect successfully.
Edited by Stan Hu