Seeming incompatibility between the Geo log cursor and database load balancing
Summary
Seen while manually testing https://gitlab.com/gitlab-org/gitlab-ee/merge_requests/5883
With load-balancing enabled (without or without service discovery), I see the following log output in postgresql, and error in bin/geo_log_cursor
:
12:20:47 postgresql.1 | ERROR: bind message supplies 0 parameters, but prepared statement "" requires 1
12:20:47 postgresql.1 | STATEMENT: SELECT "geo_nodes".* FROM "geo_nodes" WHERE "geo_nodes"."url" = $1 LIMIT 1
12:23:55 geo-cursor.1 | /home/lupine/.gem/ruby/2.3.7/gems/peek-pg-1.3.0/lib/peek/views/pg.rb:17:in `async_exec': PG::ProtocolViolation: ERROR: bind message supplies 0 parameters, but prepared statement "" requires 1 (ActiveRecord::StatementInvalid)
12:23:55 geo-cursor.1 | : SELECT "geo_nodes".* FROM "geo_nodes" WHERE "geo_nodes"."url" = $1 LIMIT 1
12:23:55 geo-cursor.1 | from /home/lupine/.gem/ruby/2.3.7/gems/peek-pg-1.3.0/lib/peek/views/pg.rb:17:in `async_exec'
12:23:55 geo-cursor.1 | from /home/lupine/.gem/ruby/2.3.7/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql_adapter.rb:592:in `block in exec_no_cache'
12:23:55 geo-cursor.1 | from /home/lupine/.gem/ruby/2.3.7/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract_adapter.rb:484:in `block in log'
12:23:55 geo-cursor.1 | from /home/lupine/.gem/ruby/2.3.7/gems/activesupport-4.2.10/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
12:23:55 geo-cursor.1 | from /home/lupine/.gem/ruby/2.3.7/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract_adapter.rb:478:in `log'
12:23:55 geo-cursor.1 | from /home/lupine/.gem/ruby/2.3.7/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql_adapter.rb:592:in `exec_no_cache'
12:23:55 geo-cursor.1 | from /home/lupine/.gem/ruby/2.3.7/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql_adapter.rb:584:in `execute_and_clear'
12:23:55 geo-cursor.1 | from /home/lupine/.gem/ruby/2.3.7/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql/database_statements.rb:160:in `exec_query'
12:23:55 geo-cursor.1 | from /home/lupine/.gem/ruby/2.3.7/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract/database_statements.rb:356:in `select'
12:23:55 geo-cursor.1 | from /home/lupine/.gem/ruby/2.3.7/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract/database_statements.rb:32:in `select_all'
12:23:55 geo-cursor.1 | from /home/lupine/.gem/ruby/2.3.7/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract/query_cache.rb:70:in `select_all'
12:23:55 geo-cursor.1 | from /home/lupine/dev/geo/primary/gitlab/ee/lib/gitlab/database/load_balancing/connection_proxy.rb:61:in `block in read_using_load_balancer'
12:23:55 geo-cursor.1 | from /home/lupine/dev/geo/primary/gitlab/ee/lib/gitlab/database/load_balancing/load_balancer.rb:66:in `block in read_write'
12:23:55 geo-cursor.1 | from /home/lupine/dev/geo/primary/gitlab/ee/lib/gitlab/database/load_balancing/load_balancer.rb:116:in `retry_with_backoff'
12:23:55 geo-cursor.1 | from /home/lupine/dev/geo/primary/gitlab/ee/lib/gitlab/database/load_balancing/load_balancer.rb:65:in `read_write'
12:23:55 geo-cursor.1 | from /home/lupine/dev/geo/primary/gitlab/ee/lib/gitlab/database/load_balancing/load_balancer.rb:57:in `read'
12:23:55 geo-cursor.1 | from /home/lupine/dev/geo/primary/gitlab/ee/lib/gitlab/database/load_balancing/connection_proxy.rb:60:in `read_using_load_balancer'
12:23:55 geo-cursor.1 | from /home/lupine/dev/geo/primary/gitlab/ee/lib/gitlab/database/load_balancing/connection_proxy.rb:39:in `select_all'
12:23:55 geo-cursor.1 | from /home/lupine/.gem/ruby/2.3.7/gems/activerecord-4.2.10/lib/active_record/querying.rb:39:in `find_by_sql'
12:23:55 geo-cursor.1 | from /home/lupine/.gem/ruby/2.3.7/gems/activerecord-4.2.10/lib/active_record/statement_cache.rb:107:in `execute'
12:23:55 geo-cursor.1 | from /home/lupine/.gem/ruby/2.3.7/gems/activerecord-4.2.10/lib/active_record/core.rb:187:in `find_by'
12:23:55 geo-cursor.1 | from /home/lupine/dev/geo/primary/gitlab/ee/app/models/geo_node.rb:65:in `current_node'
12:23:55 geo-cursor.1 | from /home/lupine/dev/geo/primary/gitlab/ee/lib/gitlab/geo.rb:18:in `block in current_node'
12:23:55 geo-cursor.1 | from /home/lupine/dev/geo/primary/gitlab/ee/lib/gitlab/geo.rb:83:in `cache_value'
12:23:55 geo-cursor.1 | from /home/lupine/dev/geo/primary/gitlab/ee/lib/gitlab/geo.rb:18:in `current_node'
12:23:55 geo-cursor.1 | from /home/lupine/dev/geo/primary/gitlab/ee/lib/gitlab/geo.rb:42:in `secondary?'
12:23:55 geo-cursor.1 | from /home/lupine/dev/geo/primary/gitlab/ee/lib/gitlab/geo/log_cursor/daemon.rb:23:in `run!'
12:23:55 geo-cursor.1 | from ./geo_log_cursor:44:in `<main>'
This suggests that the log cursor is incompatible with database load balancing. Unsure what's happening on gprd at present - I'll try to investigate the configuration there soon.
Steps to reproduce
Modify the config/database.yml
file read by the log cursor so it contains load-balancing, e.g.:
development:
adapter: postgresql
encoding: unicode
database: gitlabhq_development
port: 55432
pool: 6
host: "127.0.0.1"
load_balancing:
hosts:
- "127.0.0.1"
- "192.168.122.1"
Restart gitlab and observe the error. With gdk run
, the whole system fails to start.
What is the current bug behavior?
Log cursor attempts invalid SQL and crashes
What is the expected correct behavior?
Log cursor should either ignore load balancing or correctly support it. Unsure which is the best option at present.
Relevant logs and/or screenshots
(Paste any relevant logs - please use code blocks (```) to format console output, logs, and code as it's very hard to read otherwise.)
Output of checks
(If you are reporting a bug on GitLab.com, write: This bug happens on GitLab.com)
Possible fixes
(If you can, link to the line of code that might be responsible for the problem)
/cc @ash.mckenzie @yorickpeterse @stanhu