From 1f65a892197e53d8a178f6851230d2436b0c928d Mon Sep 17 00:00:00 2001 From: Hordur Freyr Yngvason Date: Tue, 20 Aug 2019 10:56:44 +0000 Subject: [PATCH 1/6] Use structured logging for DB load balancer As part of an effort to increase the observability of our database load balancing, we are moving towards structured logging. --- ee/lib/gitlab/database/load_balancing.rb | 12 ----------- ee/lib/gitlab/database/load_balancing/host.rb | 14 +++++++++++-- .../database/load_balancing/load_balancer.rb | 21 ++++++++++++++++--- .../gitlab/database/load_balancing/logger.rb | 13 ++++++++++++ 4 files changed, 43 insertions(+), 17 deletions(-) create mode 100644 ee/lib/gitlab/database/load_balancing/logger.rb diff --git a/ee/lib/gitlab/database/load_balancing.rb b/ee/lib/gitlab/database/load_balancing.rb index 0aefad8e2ba7..e4ad6711801e 100644 --- a/ee/lib/gitlab/database/load_balancing.rb +++ b/ee/lib/gitlab/database/load_balancing.rb @@ -1,15 +1,11 @@ # frozen_string_literal: true -# rubocop:disable GitlabSecurity/PublicSend - module Gitlab module Database module LoadBalancing # The connection proxy to use for load balancing (if enabled). cattr_accessor :proxy - LOG_TAG = 'DB-LB'.freeze - # The exceptions raised for connection errors. CONNECTION_ERRORS = if defined?(PG) [ @@ -70,14 +66,6 @@ def self.service_discovery_configuration } end - # rubocop:disable Gitlab/RailsLogger - def self.log(level, message) - Rails.logger.tagged(LOG_TAG) do - Rails.logger.send(level, message) - end - end - # rubocop:enable Gitlab/RailsLogger - def self.pool_size ActiveRecord::Base.configurations[Rails.env]['pool'] end diff --git a/ee/lib/gitlab/database/load_balancing/host.rb b/ee/lib/gitlab/database/load_balancing/host.rb index 20011158683c..4450ba5a11f7 100644 --- a/ee/lib/gitlab/database/load_balancing/host.rb +++ b/ee/lib/gitlab/database/load_balancing/host.rb @@ -54,7 +54,11 @@ def disconnect!(timeout = 120) end def offline! - LoadBalancing.log(:warn, "Marking host #{@host} as offline") + LoadBalancing::Logger.warn( + event: :host_offline, + message: "Marking host #{@host} as offline", + db_host: @host + ) @online = false @pool.disconnect! @@ -66,7 +70,13 @@ def online? refresh_status - LoadBalancing.log(:info, "Host #{@host} came back online") if @online + if @online + LoadBalancing::Logger.info( + event: :host_online, + message: "Host #{@host} came back online", + db_host: @host + ) + end @online rescue *CONNECTION_ERRORS diff --git a/ee/lib/gitlab/database/load_balancing/load_balancer.rb b/ee/lib/gitlab/database/load_balancing/load_balancer.rb index eddfbb2beaa9..d188aa3eda0e 100644 --- a/ee/lib/gitlab/database/load_balancing/load_balancer.rb +++ b/ee/lib/gitlab/database/load_balancing/load_balancer.rb @@ -38,7 +38,18 @@ def read(&block) # # In this event we'll cycle through the secondaries at most 3 # times before using the primary instead. - if conflict_retried < @host_list.length * 3 + will_retry = conflict_retried < @host_list.length * 3 + + LoadBalancing::Logger.warn( + event: :host_query_conflict, + message: 'Query conflict on host', + conflict_retried: conflict_retried, + will_retry: will_retry, + db_host: host, + host_list_length: @host_list.length + ) + + if will_retry conflict_retried += 1 release_host else @@ -53,8 +64,12 @@ def read(&block) end end - LoadBalancing - .log(:warn, 'No secondaries were available, using primary instead') + LoadBalancing::Logger.warn( + event: :no_secondaries_available, + message: 'No secondaries were available, using primary instead', + conflict_retried: conflict_retried, + host_list_length: @host_list.length + ) read_write(&block) end diff --git a/ee/lib/gitlab/database/load_balancing/logger.rb b/ee/lib/gitlab/database/load_balancing/logger.rb new file mode 100644 index 000000000000..ee67ffcc99ce --- /dev/null +++ b/ee/lib/gitlab/database/load_balancing/logger.rb @@ -0,0 +1,13 @@ +# frozen_string_literal: true + +module Gitlab + module Database + module LoadBalancing + class Logger < ::Gitlab::JsonLogger + def self.file_name_noext + 'database_load_balancing' + end + end + end + end +end -- GitLab From eed834de6f81fa312b860bc184d2e9dd380aaa75 Mon Sep 17 00:00:00 2001 From: Hordur Freyr Yngvason Date: Tue, 20 Aug 2019 12:01:15 +0000 Subject: [PATCH 2/6] Remove test for removed method --- ee/spec/lib/gitlab/database/load_balancing_spec.rb | 8 -------- 1 file changed, 8 deletions(-) diff --git a/ee/spec/lib/gitlab/database/load_balancing_spec.rb b/ee/spec/lib/gitlab/database/load_balancing_spec.rb index 976d93819941..b34f69645ca5 100644 --- a/ee/spec/lib/gitlab/database/load_balancing_spec.rb +++ b/ee/spec/lib/gitlab/database/load_balancing_spec.rb @@ -1,14 +1,6 @@ require 'spec_helper' describe Gitlab::Database::LoadBalancing do - describe '.log' do - it 'logs a message' do - expect(Rails.logger).to receive(:info).with('boop') - - described_class.log(:info, 'boop') - end - end - describe '.configuration' do it 'returns a Hash' do config = { 'hosts' => %w(foo) } -- GitLab From 058a4af83d9ff4008a288cf87b40e1db81d80401 Mon Sep 17 00:00:00 2001 From: Hordur Freyr Yngvason Date: Tue, 20 Aug 2019 12:01:37 +0000 Subject: [PATCH 3/6] Fix infinite recursion in serialization --- ee/lib/gitlab/database/load_balancing/load_balancer.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ee/lib/gitlab/database/load_balancing/load_balancer.rb b/ee/lib/gitlab/database/load_balancing/load_balancer.rb index d188aa3eda0e..d6a2523a1493 100644 --- a/ee/lib/gitlab/database/load_balancing/load_balancer.rb +++ b/ee/lib/gitlab/database/load_balancing/load_balancer.rb @@ -45,7 +45,7 @@ def read(&block) message: 'Query conflict on host', conflict_retried: conflict_retried, will_retry: will_retry, - db_host: host, + db_host: host.host, host_list_length: @host_list.length ) -- GitLab From 39ff89917cc806df720cc68091eb6f1aa1a6d780 Mon Sep 17 00:00:00 2001 From: Hordur Freyr Yngvason Date: Tue, 20 Aug 2019 12:07:42 +0000 Subject: [PATCH 4/6] Remove variable from message --- ee/lib/gitlab/database/load_balancing/host.rb | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/ee/lib/gitlab/database/load_balancing/host.rb b/ee/lib/gitlab/database/load_balancing/host.rb index 4450ba5a11f7..72fc00e68da4 100644 --- a/ee/lib/gitlab/database/load_balancing/host.rb +++ b/ee/lib/gitlab/database/load_balancing/host.rb @@ -56,7 +56,7 @@ def disconnect!(timeout = 120) def offline! LoadBalancing::Logger.warn( event: :host_offline, - message: "Marking host #{@host} as offline", + message: 'Marking host as offline', db_host: @host ) @@ -73,7 +73,7 @@ def online? if @online LoadBalancing::Logger.info( event: :host_online, - message: "Host #{@host} came back online", + message: 'Host came back online', db_host: @host ) end -- GitLab From 07e5b5ef0a5df0299b71b2f8393ff6d5654cb761 Mon Sep 17 00:00:00 2001 From: Hordur Freyr Yngvason Date: Tue, 20 Aug 2019 13:08:17 +0000 Subject: [PATCH 5/6] Add docs for new log file --- doc/administration/logs.md | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/doc/administration/logs.md b/doc/administration/logs.md index 9030c941cadc..9b1efb610f8d 100644 --- a/doc/administration/logs.md +++ b/doc/administration/logs.md @@ -338,3 +338,12 @@ installations from source. [repocheck]: repository_checks.md [Rack Attack]: ../security/rack_attack.md [Rate Limit]: ../user/admin_area/settings/rate_limits_on_raw_endpoints.md + +## `database_load_balancing.log` + +Introduced in GitLab 12.3 for observability of [Database Load +Balancing](https://docs.gitlab.com/ee/administration/database_load_balancing.html) +when enabled. This file lives in +`/var/log/gitlab/gitlab-rails/database_load_balancing.log` for Omnibus GitLab +packages or in `/home/git/gitlab/log/database_load_balancing.log` for +installations from source. -- GitLab From 688da53c702eafbc9fcdc802ff45b815f85d2e8d Mon Sep 17 00:00:00 2001 From: Hordur Freyr Yngvason Date: Mon, 26 Aug 2019 10:15:50 +0000 Subject: [PATCH 6/6] Add port to logs for visibility on SRV lookups Just rebased on master, and now there is a port attribute that we need to include to distinguish between hosts. See https://gitlab.com/gitlab-org/gitlab-ee/merge_requests/15558/diffs --- ee/lib/gitlab/database/load_balancing/host.rb | 6 ++++-- ee/lib/gitlab/database/load_balancing/load_balancer.rb | 1 + 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/ee/lib/gitlab/database/load_balancing/host.rb b/ee/lib/gitlab/database/load_balancing/host.rb index 72fc00e68da4..be3adf185df6 100644 --- a/ee/lib/gitlab/database/load_balancing/host.rb +++ b/ee/lib/gitlab/database/load_balancing/host.rb @@ -57,7 +57,8 @@ def offline! LoadBalancing::Logger.warn( event: :host_offline, message: 'Marking host as offline', - db_host: @host + db_host: @host, + db_port: @port ) @online = false @@ -74,7 +75,8 @@ def online? LoadBalancing::Logger.info( event: :host_online, message: 'Host came back online', - db_host: @host + db_host: @host, + db_port: @port ) end diff --git a/ee/lib/gitlab/database/load_balancing/load_balancer.rb b/ee/lib/gitlab/database/load_balancing/load_balancer.rb index d6a2523a1493..9668039a4c26 100644 --- a/ee/lib/gitlab/database/load_balancing/load_balancer.rb +++ b/ee/lib/gitlab/database/load_balancing/load_balancer.rb @@ -46,6 +46,7 @@ def read(&block) conflict_retried: conflict_retried, will_retry: will_retry, db_host: host.host, + db_port: host.port, host_list_length: @host_list.length ) -- GitLab