From 966045a40c7568b7527767f70a7428806ca86509 Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Thu, 15 Oct 2020 16:42:58 +0200 Subject: [PATCH 01/11] Add JSON log file for gitaly-ruby --- ruby/bin/gitaly-ruby | 2 + ruby/lib/gitaly_server/logging_interceptor.rb | 100 ++++++++++++++++++ 2 files changed, 102 insertions(+) create mode 100644 ruby/lib/gitaly_server/logging_interceptor.rb diff --git a/ruby/bin/gitaly-ruby b/ruby/bin/gitaly-ruby index 257226b57b..47d50fef9d 100755 --- a/ruby/bin/gitaly-ruby +++ b/ruby/bin/gitaly-ruby @@ -13,6 +13,7 @@ require 'gitlab-labkit' require 'rugged' require_relative '../lib/gitaly_server.rb' +require_relative '../lib/gitaly_server/logging_interceptor.rb' require_relative '../lib/gitaly_server/sentry_interceptor.rb' require_relative '../lib/gitaly_server/exception_sanitizer_interceptor.rb' require_relative '../lib/gitaly_server/rugged_interceptor.rb' @@ -116,6 +117,7 @@ end def build_server_interceptor_chain chain = [] chain << Labkit::Correlation::GRPC::ServerInterceptor.new + chain << GitalyServer::LoggingInterceptor.new chain << GitalyServer::SentryInterceptor.new chain << Labkit::Tracing::GRPC::ServerInterceptor.new if Labkit::Tracing.enabled? chain << GitalyServer::ExceptionSanitizerInterceptor.new diff --git a/ruby/lib/gitaly_server/logging_interceptor.rb b/ruby/lib/gitaly_server/logging_interceptor.rb new file mode 100644 index 0000000000..322f0c8e98 --- /dev/null +++ b/ruby/lib/gitaly_server/logging_interceptor.rb @@ -0,0 +1,100 @@ +require 'grpc' +require 'active_support/core_ext/string/inflections' +require 'json' + +module GitalyServer + class LoggingInterceptor < GRPC::ServerInterceptor + CodeStrings = { + GRPC::Core::StatusCodes::OK => 'OK', + GRPC::Core::StatusCodes::CANCELLED => 'Canceled', + GRPC::Core::StatusCodes::UNKNOWN => 'Unknown', + GRPC::Core::StatusCodes::INVALID_ARGUMENT => 'InvalidArgument', + GRPC::Core::StatusCodes::DEADLINE_EXCEEDED => 'DeadlineExceeded', + GRPC::Core::StatusCodes::NOT_FOUND => 'NotFound', + GRPC::Core::StatusCodes::ALREADY_EXISTS => 'AlreadyExists', + GRPC::Core::StatusCodes::PERMISSION_DENIED => 'PermissionDenied', + GRPC::Core::StatusCodes::RESOURCE_EXHAUSTED => 'ResourceExhausted', + GRPC::Core::StatusCodes::FAILED_PRECONDITION => 'FailedPrecondition', + GRPC::Core::StatusCodes::ABORTED => 'Aborted', + GRPC::Core::StatusCodes::OUT_OF_RANGE => 'OutOfRange', + GRPC::Core::StatusCodes::UNIMPLEMENTED => 'Unimplemented', + GRPC::Core::StatusCodes::INTERNAL => 'Internal', + GRPC::Core::StatusCodes::UNAVAILABLE => 'Unavailable', + GRPC::Core::StatusCodes::DATA_LOSS => 'DataLoss', + GRPC::Core::StatusCodes::UNAUTHENTICATED => 'Unauthenticated' + }.freeze + + def initialize + @log_mutex = Mutex.new + super + end + + def request_response(request: nil, call: nil, method: nil) + start = Time.now + code = GRPC::Core::StatusCodes::OK + + yield + rescue => e + code = e.code if e.is_a?(GRPC::BadStatus) + raise + ensure + log_request(method, call, code, start) + end + + def server_streamer(request: nil, call: nil, method: nil) + start = Time.now + code = GRPC::Core::StatusCodes::OK + + yield + rescue => e + code = e.code if e.is_a?(GRPC::BadStatus) + raise + ensure + log_request(method, call, code, start) + end + + def client_streamer(call: nil, method: nil) + start = Time.now + code = GRPC::Core::StatusCodes::OK + + yield + rescue => e + code = e.code if e.is_a?(GRPC::BadStatus) + raise + ensure + log_request(method, call, code, start) + end + + def bidi_streamer(requests: nil, call: nil, method: nil) + yield + rescue => e + code = e.code if e.is_a?(GRPC::BadStatus) + raise + ensure + log_request(method, call, code, start) + end + + private + + def log_request(method, call, code, start) + log({ + type: 'gitaly-ruby', + duration: (Time.now - start).to_f, + code: CodeStrings[code] || code, + method: method.name.to_s.camelize, + service: method.owner.service_name, + pid: Process.pid, + correlation_id: call.metadata['x-gitlab-correlation-id'], + time: Time.now.utc.strftime('%Y-%m-%dT%H:%M:%S.%LZ') + }) + end + + def log(msg) + @log_mutex.synchronize do + @log_file ||= File.open(File.join(ENV['GITALY_LOG_DIR'], 'gitaly_ruby_json.log'), 'a') + @log_file.sync = true + @log_file.puts(JSON.dump(msg)) + end + end + end +end -- GitLab From ae60852b9206c750140e03d95695945ade173aa2 Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Thu, 15 Oct 2020 16:46:11 +0200 Subject: [PATCH 02/11] Add frozen string literal --- ruby/lib/gitaly_server/logging_interceptor.rb | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/ruby/lib/gitaly_server/logging_interceptor.rb b/ruby/lib/gitaly_server/logging_interceptor.rb index 322f0c8e98..92ed8c4ffc 100644 --- a/ruby/lib/gitaly_server/logging_interceptor.rb +++ b/ruby/lib/gitaly_server/logging_interceptor.rb @@ -1,4 +1,6 @@ -require 'grpc' +# frozen_string_literal: truer + +equire 'grpc' require 'active_support/core_ext/string/inflections' require 'json' -- GitLab From 4d8b5c2d0fbeb71236418acee10956622e13b755 Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Thu, 15 Oct 2020 17:00:06 +0200 Subject: [PATCH 03/11] Fix rubocop offenses --- ruby/.rubocop_todo.yml | 1 + ruby/lib/gitaly_server/logging_interceptor.rb | 42 ++++++++++--------- 2 files changed, 23 insertions(+), 20 deletions(-) diff --git a/ruby/.rubocop_todo.yml b/ruby/.rubocop_todo.yml index 87453d9e64..b7b33a7d2a 100644 --- a/ruby/.rubocop_todo.yml +++ b/ruby/.rubocop_todo.yml @@ -74,6 +74,7 @@ Lint/SuppressedException: # Configuration parameters: AllowUnusedKeywordArguments, IgnoreEmptyMethods, IgnoreNotImplementedMethods. Lint/UnusedMethodArgument: Exclude: + - 'lib/gitaly_server/logging_interceptor.rb' - 'lib/gitaly_server/sentry_interceptor.rb' - 'lib/gitlab/git/conflict/parser.rb' diff --git a/ruby/lib/gitaly_server/logging_interceptor.rb b/ruby/lib/gitaly_server/logging_interceptor.rb index 92ed8c4ffc..ad5e644b5f 100644 --- a/ruby/lib/gitaly_server/logging_interceptor.rb +++ b/ruby/lib/gitaly_server/logging_interceptor.rb @@ -1,12 +1,12 @@ # frozen_string_literal: truer -equire 'grpc' +require 'grpc' require 'active_support/core_ext/string/inflections' require 'json' module GitalyServer class LoggingInterceptor < GRPC::ServerInterceptor - CodeStrings = { + CODE_STRINGS = { GRPC::Core::StatusCodes::OK => 'OK', GRPC::Core::StatusCodes::CANCELLED => 'Canceled', GRPC::Core::StatusCodes::UNKNOWN => 'Unknown', @@ -36,8 +36,8 @@ module GitalyServer code = GRPC::Core::StatusCodes::OK yield - rescue => e - code = e.code if e.is_a?(GRPC::BadStatus) + rescue GRPC::BadStatus => e + code = e.code raise ensure log_request(method, call, code, start) @@ -48,8 +48,8 @@ module GitalyServer code = GRPC::Core::StatusCodes::OK yield - rescue => e - code = e.code if e.is_a?(GRPC::BadStatus) + rescue GRPC::BadStatus => e + code = e.code raise ensure log_request(method, call, code, start) @@ -60,8 +60,8 @@ module GitalyServer code = GRPC::Core::StatusCodes::OK yield - rescue => e - code = e.code if e.is_a?(GRPC::BadStatus) + rescue GRPC::BadStatus => e + code = e.code raise ensure log_request(method, call, code, start) @@ -69,8 +69,8 @@ module GitalyServer def bidi_streamer(requests: nil, call: nil, method: nil) yield - rescue => e - code = e.code if e.is_a?(GRPC::BadStatus) + rescue GRPC::BadStatus => e + code = e.code raise ensure log_request(method, call, code, start) @@ -79,16 +79,18 @@ module GitalyServer private def log_request(method, call, code, start) - log({ - type: 'gitaly-ruby', - duration: (Time.now - start).to_f, - code: CodeStrings[code] || code, - method: method.name.to_s.camelize, - service: method.owner.service_name, - pid: Process.pid, - correlation_id: call.metadata['x-gitlab-correlation-id'], - time: Time.now.utc.strftime('%Y-%m-%dT%H:%M:%S.%LZ') - }) + log( + { + type: 'gitaly-ruby', + duration: (Time.now - start).to_f, + code: CODE_STRINGS[code] || code, + method: method.name.to_s.camelize, + service: method.owner.service_name, + pid: Process.pid, + correlation_id: call.metadata['x-gitlab-correlation-id'], + time: Time.now.utc.strftime('%Y-%m-%dT%H:%M:%S.%LZ') + } + ) end def log(msg) -- GitLab From f2e5141d685f440a710a428daecfd3c96b082ad5 Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Thu, 15 Oct 2020 17:03:52 +0200 Subject: [PATCH 04/11] Log code as string --- ruby/lib/gitaly_server/logging_interceptor.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ruby/lib/gitaly_server/logging_interceptor.rb b/ruby/lib/gitaly_server/logging_interceptor.rb index ad5e644b5f..4fa83e7542 100644 --- a/ruby/lib/gitaly_server/logging_interceptor.rb +++ b/ruby/lib/gitaly_server/logging_interceptor.rb @@ -83,7 +83,7 @@ module GitalyServer { type: 'gitaly-ruby', duration: (Time.now - start).to_f, - code: CODE_STRINGS[code] || code, + code: CODE_STRINGS[code] || code.to_s, method: method.name.to_s.camelize, service: method.owner.service_name, pid: Process.pid, -- GitLab From 83376316103ca61dcbc5feff32a2530fe5af79ac Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Thu, 15 Oct 2020 17:27:21 +0200 Subject: [PATCH 05/11] Decouple logging interceptor from gitaly-ruby --- ruby/bin/gitaly-ruby | 5 ++++- ruby/lib/gitaly_server/logging_interceptor.rb | 21 +++++++++---------- 2 files changed, 14 insertions(+), 12 deletions(-) diff --git a/ruby/bin/gitaly-ruby b/ruby/bin/gitaly-ruby index 47d50fef9d..ec1d95a73b 100755 --- a/ruby/bin/gitaly-ruby +++ b/ruby/bin/gitaly-ruby @@ -117,7 +117,10 @@ end def build_server_interceptor_chain chain = [] chain << Labkit::Correlation::GRPC::ServerInterceptor.new - chain << GitalyServer::LoggingInterceptor.new + chain << GitalyServer::LoggingInterceptor.new( + File.open(File.join(ENV['GITALY_LOG_DIR'], 'gitaly_ruby_json.log'), 'a'), + { type: 'gitaly-ruby' } + ) chain << GitalyServer::SentryInterceptor.new chain << Labkit::Tracing::GRPC::ServerInterceptor.new if Labkit::Tracing.enabled? chain << GitalyServer::ExceptionSanitizerInterceptor.new diff --git a/ruby/lib/gitaly_server/logging_interceptor.rb b/ruby/lib/gitaly_server/logging_interceptor.rb index 4fa83e7542..bab4da8940 100644 --- a/ruby/lib/gitaly_server/logging_interceptor.rb +++ b/ruby/lib/gitaly_server/logging_interceptor.rb @@ -26,9 +26,12 @@ module GitalyServer GRPC::Core::StatusCodes::UNAUTHENTICATED => 'Unauthenticated' }.freeze - def initialize - @log_mutex = Mutex.new - super + def initialize(log_file, default_tags) + @log_file = log_file + @log_file.sync = true if @log_file.respond_to?(:sync=) + @default_tags = default_tags + + super() end def request_response(request: nil, call: nil, method: nil) @@ -79,9 +82,8 @@ module GitalyServer private def log_request(method, call, code, start) - log( + message = @default_tags.merge( { - type: 'gitaly-ruby', duration: (Time.now - start).to_f, code: CODE_STRINGS[code] || code.to_s, method: method.name.to_s.camelize, @@ -91,14 +93,11 @@ module GitalyServer time: Time.now.utc.strftime('%Y-%m-%dT%H:%M:%S.%LZ') } ) + log(message) end - def log(msg) - @log_mutex.synchronize do - @log_file ||= File.open(File.join(ENV['GITALY_LOG_DIR'], 'gitaly_ruby_json.log'), 'a') - @log_file.sync = true - @log_file.puts(JSON.dump(msg)) - end + def log(message) + @log_file.puts(JSON.dump(message)) end end end -- GitLab From 25b8afb9617af10588781c8099cb0b5d4405f1d1 Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Thu, 15 Oct 2020 17:30:12 +0200 Subject: [PATCH 06/11] Fix typo --- ruby/lib/gitaly_server/logging_interceptor.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ruby/lib/gitaly_server/logging_interceptor.rb b/ruby/lib/gitaly_server/logging_interceptor.rb index bab4da8940..72c2e69303 100644 --- a/ruby/lib/gitaly_server/logging_interceptor.rb +++ b/ruby/lib/gitaly_server/logging_interceptor.rb @@ -1,4 +1,4 @@ -# frozen_string_literal: truer +# frozen_string_literal: true require 'grpc' require 'active_support/core_ext/string/inflections' -- GitLab From 6a0b1c380bf7d0ec6dc9e2c989bae40cf32cdfeb Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Thu, 15 Oct 2020 17:31:27 +0200 Subject: [PATCH 07/11] Add missing variables --- ruby/lib/gitaly_server/logging_interceptor.rb | 3 +++ 1 file changed, 3 insertions(+) diff --git a/ruby/lib/gitaly_server/logging_interceptor.rb b/ruby/lib/gitaly_server/logging_interceptor.rb index 72c2e69303..fcbc9ef16f 100644 --- a/ruby/lib/gitaly_server/logging_interceptor.rb +++ b/ruby/lib/gitaly_server/logging_interceptor.rb @@ -71,6 +71,9 @@ module GitalyServer end def bidi_streamer(requests: nil, call: nil, method: nil) + start = Time.now + code = GRPC::Core::StatusCodes::OK + yield rescue GRPC::BadStatus => e code = e.code -- GitLab From 4216675fdd3dda681684eb0a7ebecd6068a52b4b Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Thu, 15 Oct 2020 18:02:31 +0200 Subject: [PATCH 08/11] Fix rescues --- ruby/.rubocop_todo.yml | 1 + ruby/lib/gitaly_server/logging_interceptor.rb | 16 ++++++++-------- 2 files changed, 9 insertions(+), 8 deletions(-) diff --git a/ruby/.rubocop_todo.yml b/ruby/.rubocop_todo.yml index b7b33a7d2a..8b0b6d9c04 100644 --- a/ruby/.rubocop_todo.yml +++ b/ruby/.rubocop_todo.yml @@ -234,6 +234,7 @@ Style/RedundantSelf: Style/RescueStandardError: Exclude: - 'lib/gitaly_server/exception_sanitizer_interceptor.rb' + - 'lib/gitaly_server/logging_interceptor.rb' - 'lib/gitaly_server/sentry_interceptor.rb' - 'spec/lib/gitaly_server/exception_sanitizer_interceptor_spec.rb' - 'spec/lib/gitaly_server/sentry/url_sanitizer_spec.rb' diff --git a/ruby/lib/gitaly_server/logging_interceptor.rb b/ruby/lib/gitaly_server/logging_interceptor.rb index fcbc9ef16f..81f01b6561 100644 --- a/ruby/lib/gitaly_server/logging_interceptor.rb +++ b/ruby/lib/gitaly_server/logging_interceptor.rb @@ -39,8 +39,8 @@ module GitalyServer code = GRPC::Core::StatusCodes::OK yield - rescue GRPC::BadStatus => e - code = e.code + rescue => e + code = e.code if e.is_a?(GRPC::BadStatus) raise ensure log_request(method, call, code, start) @@ -51,8 +51,8 @@ module GitalyServer code = GRPC::Core::StatusCodes::OK yield - rescue GRPC::BadStatus => e - code = e.code + rescue => e + code = e.code if e.is_a?(GRPC::BadStatus) raise ensure log_request(method, call, code, start) @@ -63,8 +63,8 @@ module GitalyServer code = GRPC::Core::StatusCodes::OK yield - rescue GRPC::BadStatus => e - code = e.code + rescue => e + code = e.code if e.is_a?(GRPC::BadStatus) raise ensure log_request(method, call, code, start) @@ -75,8 +75,8 @@ module GitalyServer code = GRPC::Core::StatusCodes::OK yield - rescue GRPC::BadStatus => e - code = e.code + rescue => e + code = e.code if e.is_a?(GRPC::BadStatus) raise ensure log_request(method, call, code, start) -- GitLab From f2b14ef48acc1597758aff65ebcd00813e9bd402 Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Thu, 15 Oct 2020 18:19:04 +0200 Subject: [PATCH 09/11] More code reuse --- ruby/lib/gitaly_server/logging_interceptor.rb | 50 ++++++------------- 1 file changed, 14 insertions(+), 36 deletions(-) diff --git a/ruby/lib/gitaly_server/logging_interceptor.rb b/ruby/lib/gitaly_server/logging_interceptor.rb index 81f01b6561..9e049ee8af 100644 --- a/ruby/lib/gitaly_server/logging_interceptor.rb +++ b/ruby/lib/gitaly_server/logging_interceptor.rb @@ -35,56 +35,33 @@ module GitalyServer end def request_response(request: nil, call: nil, method: nil) - start = Time.now - code = GRPC::Core::StatusCodes::OK - - yield - rescue => e - code = e.code if e.is_a?(GRPC::BadStatus) - raise - ensure - log_request(method, call, code, start) + log_request(method, call) { yield } end def server_streamer(request: nil, call: nil, method: nil) - start = Time.now - code = GRPC::Core::StatusCodes::OK - - yield - rescue => e - code = e.code if e.is_a?(GRPC::BadStatus) - raise - ensure - log_request(method, call, code, start) + log_request(method, call) { yield } end def client_streamer(call: nil, method: nil) - start = Time.now - code = GRPC::Core::StatusCodes::OK - - yield - rescue => e - code = e.code if e.is_a?(GRPC::BadStatus) - raise - ensure - log_request(method, call, code, start) + log_request(method, call) { yield } end def bidi_streamer(requests: nil, call: nil, method: nil) + log_request(method, call) { yield } + end + + private + + def log_request(method, call, &block) start = Time.now code = GRPC::Core::StatusCodes::OK - yield - rescue => e - code = e.code if e.is_a?(GRPC::BadStatus) + block.call + rescue => ex + code = ex.is_a?(GRPC::BadStatus) ? ex.code : GRPC::Core::StatusCodes::UNAVAILABLE + raise ensure - log_request(method, call, code, start) - end - - private - - def log_request(method, call, code, start) message = @default_tags.merge( { duration: (Time.now - start).to_f, @@ -96,6 +73,7 @@ module GitalyServer time: Time.now.utc.strftime('%Y-%m-%dT%H:%M:%S.%LZ') } ) + log(message) end -- GitLab From 0aaf6a5faf307df76459980cafca998ef706e8f4 Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Fri, 16 Oct 2020 10:30:35 +0200 Subject: [PATCH 10/11] Update fields, fix method name lookup --- ruby/lib/gitaly_server/logging_interceptor.rb | 21 +++++++++++-------- 1 file changed, 12 insertions(+), 9 deletions(-) diff --git a/ruby/lib/gitaly_server/logging_interceptor.rb b/ruby/lib/gitaly_server/logging_interceptor.rb index 9e049ee8af..c157c5a33c 100644 --- a/ruby/lib/gitaly_server/logging_interceptor.rb +++ b/ruby/lib/gitaly_server/logging_interceptor.rb @@ -1,7 +1,6 @@ # frozen_string_literal: true require 'grpc' -require 'active_support/core_ext/string/inflections' require 'json' module GitalyServer @@ -28,7 +27,7 @@ module GitalyServer def initialize(log_file, default_tags) @log_file = log_file - @log_file.sync = true if @log_file.respond_to?(:sync=) + @log_file.sync = true @default_tags = default_tags super() @@ -64,21 +63,25 @@ module GitalyServer ensure message = @default_tags.merge( { - duration: (Time.now - start).to_f, - code: CODE_STRINGS[code] || code.to_s, - method: method.name.to_s.camelize, - service: method.owner.service_name, + 'grpc.time_ms': ((Time.now - start) * 1000.0).truncate(3), + 'grpc.code': CODE_STRINGS[code] || code.to_s, + 'grpc.method': method_name(method) || '(Unknown)', + 'grpc.service': method.owner.service_name, pid: Process.pid, correlation_id: call.metadata['x-gitlab-correlation-id'], time: Time.now.utc.strftime('%Y-%m-%dT%H:%M:%S.%LZ') } ) - log(message) + @log_file.puts(JSON.dump(message)) end - def log(message) - @log_file.puts(JSON.dump(message)) + def method_name(method) + result, _ = method.owner.rpc_descs.find do |k, _| + GRPC::GenericService.underscore(k.to_s) == method.name.to_s + end + + result end end end -- GitLab From 2eef34bf2117b2397e35e745b3a879a1cbc71205 Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Fri, 16 Oct 2020 12:03:00 +0200 Subject: [PATCH 11/11] Fix rubocop --- ruby/lib/gitaly_server/logging_interceptor.rb | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/ruby/lib/gitaly_server/logging_interceptor.rb b/ruby/lib/gitaly_server/logging_interceptor.rb index c157c5a33c..d69abe2b71 100644 --- a/ruby/lib/gitaly_server/logging_interceptor.rb +++ b/ruby/lib/gitaly_server/logging_interceptor.rb @@ -65,7 +65,7 @@ module GitalyServer { 'grpc.time_ms': ((Time.now - start) * 1000.0).truncate(3), 'grpc.code': CODE_STRINGS[code] || code.to_s, - 'grpc.method': method_name(method) || '(Unknown)', + 'grpc.method': method_name(method) || '(Unknown)', 'grpc.service': method.owner.service_name, pid: Process.pid, correlation_id: call.metadata['x-gitlab-correlation-id'], @@ -77,7 +77,7 @@ module GitalyServer end def method_name(method) - result, _ = method.owner.rpc_descs.find do |k, _| + result, = method.owner.rpc_descs.find do |k, _| GRPC::GenericService.underscore(k.to_s) == method.name.to_s end -- GitLab