From d14eea3c81ddb45f96cd6adf4ab880a01775d85e Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Tue, 20 Oct 2020 15:40:11 +0200 Subject: [PATCH 1/8] Add JSON request logging for gitaly-ruby --- doc/logging.md | 7 +++++++ ruby/Gemfile | 2 +- ruby/Gemfile.lock | 8 ++++---- ruby/bin/gitaly-ruby | 4 ++++ 4 files changed, 16 insertions(+), 5 deletions(-) diff --git a/doc/logging.md b/doc/logging.md index 88250be7c..98d0e4ce4 100644 --- a/doc/logging.md +++ b/doc/logging.md @@ -22,6 +22,7 @@ include them in its main log, tagged with the request correlation ID. ## Gitaly-ruby application logs +### Unstructured logs Gitaly-ruby writes logs to stdout. These logs are not structured. The main Gitaly process captures the gitaly-ruby process log messages and converts each line into a structured message that includes information @@ -37,6 +38,12 @@ Because of these properties, gitaly-ruby logs are often hard to read, and it is often not possible to attribute log messages to individual RPC requests. +### Structured logs + +Gitaly-ruby also writes a JSON structured log file with access log +information (method, duration, response code). It can be found in +`gitaly_ruby_json.log`. + ## Log files In a few cases, Gitaly spawns process that cannot log to stderr diff --git a/ruby/Gemfile b/ruby/Gemfile index 9016a64a0..928438284 100644 --- a/ruby/Gemfile +++ b/ruby/Gemfile @@ -16,7 +16,7 @@ gem 'faraday', '~> 1.0' gem 'rbtrace', require: false # Labkit provides observability functionality -gem 'gitlab-labkit', '~> 0.12.0' +gem 'gitlab-labkit', '~> 0.13.0' # Detects the open source license the repository includes # This version needs to be in sync with GitLab CE/EE diff --git a/ruby/Gemfile.lock b/ruby/Gemfile.lock index e3d1a833b..a5cc4db20 100644 --- a/ruby/Gemfile.lock +++ b/ruby/Gemfile.lock @@ -67,7 +67,7 @@ GEM gitlab-gollum-rugged_adapter (0.4.4.2) mime-types (>= 1.15) rugged (~> 0.25) - gitlab-labkit (0.12.0) + gitlab-labkit (0.13.0) actionpack (>= 5.0.0, < 6.1.0) activesupport (>= 5.0.0, < 6.1.0) grpc (~> 1.19) @@ -139,7 +139,7 @@ GEM msgpack (>= 0.4.3) optimist (>= 3.0.0) rdoc (6.2.0) - redis (4.1.3) + redis (4.2.2) regexp_parser (1.8.1) rexml (3.2.4) rouge (3.24.0) @@ -189,7 +189,7 @@ GEM simplecov-html (0.10.2) stringex (2.8.5) thread_safe (0.3.6) - thrift (0.11.0.0) + thrift (0.13.0) timecop (0.9.1) tzinfo (1.2.7) thread_safe (~> 0.1) @@ -220,7 +220,7 @@ DEPENDENCIES github-linguist (~> 7.11) gitlab-gollum-lib (~> 4.2.7.9) gitlab-gollum-rugged_adapter (~> 0.4.4.2) - gitlab-labkit (~> 0.12.0) + gitlab-labkit (~> 0.13.0) gitlab-markup (~> 1.7.1) google-protobuf (~> 3.12) grpc (~> 1.30.2) diff --git a/ruby/bin/gitaly-ruby b/ruby/bin/gitaly-ruby index 257226b57..ae971434f 100755 --- a/ruby/bin/gitaly-ruby +++ b/ruby/bin/gitaly-ruby @@ -116,6 +116,10 @@ end def build_server_interceptor_chain chain = [] chain << Labkit::Correlation::GRPC::ServerInterceptor.new + chain << Labkit::Logging::GRPC::ServerInterceptor.new( + File.open(File.join(Gitlab.config.logging.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 -- GitLab From dd9b691f91a759837cf6bde285b6c285b89f7f5e Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Tue, 20 Oct 2020 15:42:02 +0200 Subject: [PATCH 2/8] Mention log file twice to be sure --- doc/logging.md | 1 + 1 file changed, 1 insertion(+) diff --git a/doc/logging.md b/doc/logging.md index 98d0e4ce4..040a1e3e1 100644 --- a/doc/logging.md +++ b/doc/logging.md @@ -57,6 +57,7 @@ Examples are: - `gitlab-shell.log` - `gitaly_hooks.log` +- `gitaly_ruby_json.log` There is another log file called `githost.log`. This log is generated by legacy code in gitaly-ruby. The way it is used, it might as well -- GitLab From 1a0fdfbda5830f5e7e724ed9a58f5cc6de0c1895 Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Tue, 20 Oct 2020 15:43:19 +0200 Subject: [PATCH 3/8] changelog --- changelogs/unreleased/jv-ruby-log-3.yml | 5 +++++ 1 file changed, 5 insertions(+) create mode 100644 changelogs/unreleased/jv-ruby-log-3.yml diff --git a/changelogs/unreleased/jv-ruby-log-3.yml b/changelogs/unreleased/jv-ruby-log-3.yml new file mode 100644 index 000000000..4ba8f88dd --- /dev/null +++ b/changelogs/unreleased/jv-ruby-log-3.yml @@ -0,0 +1,5 @@ +--- +title: Add JSON request logging for gitaly-ruby +merge_request: 2678 +author: +type: added -- GitLab From 97f86de94a1e48c8285ec26796babe141cf3d20f Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Tue, 20 Oct 2020 15:46:37 +0200 Subject: [PATCH 4/8] Reset unrelated gem versions --- ruby/Gemfile.lock | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/ruby/Gemfile.lock b/ruby/Gemfile.lock index a5cc4db20..bcc6e580f 100644 --- a/ruby/Gemfile.lock +++ b/ruby/Gemfile.lock @@ -139,7 +139,7 @@ GEM msgpack (>= 0.4.3) optimist (>= 3.0.0) rdoc (6.2.0) - redis (4.2.2) + redis (4.1.3) regexp_parser (1.8.1) rexml (3.2.4) rouge (3.24.0) @@ -189,7 +189,7 @@ GEM simplecov-html (0.10.2) stringex (2.8.5) thread_safe (0.3.6) - thrift (0.13.0) + thrift (0.11.0.0) timecop (0.9.1) tzinfo (1.2.7) thread_safe (~> 0.1) -- GitLab From 4b3a6982d9583d4c31a389de8bca679c1ddbffae Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Tue, 20 Oct 2020 15:47:18 +0200 Subject: [PATCH 5/8] Whitespace --- doc/logging.md | 1 + 1 file changed, 1 insertion(+) diff --git a/doc/logging.md b/doc/logging.md index 040a1e3e1..da6d9705e 100644 --- a/doc/logging.md +++ b/doc/logging.md @@ -23,6 +23,7 @@ include them in its main log, tagged with the request correlation ID. ## Gitaly-ruby application logs ### Unstructured logs + Gitaly-ruby writes logs to stdout. These logs are not structured. The main Gitaly process captures the gitaly-ruby process log messages and converts each line into a structured message that includes information -- GitLab From 7256c53312415221bd072182ae49aa3a00b381ec Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Tue, 20 Oct 2020 16:55:17 +0200 Subject: [PATCH 6/8] Allow missing logging directory --- ruby/bin/gitaly-ruby | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/ruby/bin/gitaly-ruby b/ruby/bin/gitaly-ruby index ae971434f..1e9a269cf 100755 --- a/ruby/bin/gitaly-ruby +++ b/ruby/bin/gitaly-ruby @@ -116,10 +116,14 @@ end def build_server_interceptor_chain chain = [] chain << Labkit::Correlation::GRPC::ServerInterceptor.new - chain << Labkit::Logging::GRPC::ServerInterceptor.new( - File.open(File.join(Gitlab.config.logging.dir, 'gitaly_ruby_json.log'), 'a'), - { type: 'gitaly-ruby' } - ) + + if Gitlab.config.logging.dir.present? + chain << Labkit::Logging::GRPC::ServerInterceptor.new( + File.open(File.join(Gitlab.config.logging.dir, 'gitaly_ruby_json.log'), 'a'), + { type: 'gitaly-ruby' } + ) + end + chain << GitalyServer::SentryInterceptor.new chain << Labkit::Tracing::GRPC::ServerInterceptor.new if Labkit::Tracing.enabled? chain << GitalyServer::ExceptionSanitizerInterceptor.new -- GitLab From 2fcb573312176c6fc651d67c43fe265773328d4c Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Wed, 21 Oct 2020 10:50:01 +0200 Subject: [PATCH 7/8] Configure logging directory during test setup --- .gitignore | 1 + internal/testhelper/testhelper.go | 20 ++++++++++++++------ ruby/bin/gitaly-ruby | 12 ++++-------- 3 files changed, 19 insertions(+), 14 deletions(-) diff --git a/.gitignore b/.gitignore index 73ed47cec..f60146ba5 100644 --- a/.gitignore +++ b/.gitignore @@ -25,6 +25,7 @@ /internal/service/smarthttp/testdata /internal/testhelper/testdata/data /**/testdata/gitaly-libexec +/**/testdata/log # Configuration and runtime data /*.toml diff --git a/internal/testhelper/testhelper.go b/internal/testhelper/testhelper.go index a296d34fa..380d0c029 100644 --- a/internal/testhelper/testhelper.go +++ b/internal/testhelper/testhelper.go @@ -90,12 +90,20 @@ func Configure() { config.Config.InternalSocketDir = dir - if err := os.MkdirAll("testdata/gitaly-libexec", 0755); err != nil { - log.Fatal(err) - } - config.Config.BinDir, err = filepath.Abs("testdata/gitaly-libexec") - if err != nil { - log.Fatal(err) + for _, d := range []struct { + dir string + cfg *string + }{ + {dir: "testdata/gitaly-libexec", cfg: &config.Config.BinDir}, + {dir: "testdata/log", cfg: &config.Config.Logging.Dir}, + } { + if err := os.MkdirAll(d.dir, 0755); err != nil { + log.Fatal(err) + } + *d.cfg, err = filepath.Abs(d.dir) + if err != nil { + log.Fatal(err) + } } for _, f := range []func() error{ diff --git a/ruby/bin/gitaly-ruby b/ruby/bin/gitaly-ruby index 1e9a269cf..ae971434f 100755 --- a/ruby/bin/gitaly-ruby +++ b/ruby/bin/gitaly-ruby @@ -116,14 +116,10 @@ end def build_server_interceptor_chain chain = [] chain << Labkit::Correlation::GRPC::ServerInterceptor.new - - if Gitlab.config.logging.dir.present? - chain << Labkit::Logging::GRPC::ServerInterceptor.new( - File.open(File.join(Gitlab.config.logging.dir, 'gitaly_ruby_json.log'), 'a'), - { type: 'gitaly-ruby' } - ) - end - + chain << Labkit::Logging::GRPC::ServerInterceptor.new( + File.open(File.join(Gitlab.config.logging.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 -- GitLab From d9cbf38a389570b4d3d3134cd4d8a72d90c2f679 Mon Sep 17 00:00:00 2001 From: Jacob Vosmaer Date: Fri, 23 Oct 2020 16:31:47 +0200 Subject: [PATCH 8/8] Clear log directory before tests start --- internal/testhelper/testhelper.go | 32 +++++++++++++++++-------------- 1 file changed, 18 insertions(+), 14 deletions(-) diff --git a/internal/testhelper/testhelper.go b/internal/testhelper/testhelper.go index 380d0c029..4d356a54a 100644 --- a/internal/testhelper/testhelper.go +++ b/internal/testhelper/testhelper.go @@ -76,6 +76,18 @@ func Configure() { configureOnce.Do(func() { gitalylog.Configure("json", "info") + var err error + config.Config.Logging.Dir, err = filepath.Abs("testdata/log") + if err != nil { + log.Fatal(err) + } + if err := os.RemoveAll(config.Config.Logging.Dir); err != nil { + log.Fatal(err) + } + if err := os.MkdirAll(config.Config.Logging.Dir, 0755); err != nil { + log.Fatal(err) + } + config.Config.Storages = []config.Storage{ {Name: "default", Path: GitlabTestStoragePath()}, } @@ -90,20 +102,12 @@ func Configure() { config.Config.InternalSocketDir = dir - for _, d := range []struct { - dir string - cfg *string - }{ - {dir: "testdata/gitaly-libexec", cfg: &config.Config.BinDir}, - {dir: "testdata/log", cfg: &config.Config.Logging.Dir}, - } { - if err := os.MkdirAll(d.dir, 0755); err != nil { - log.Fatal(err) - } - *d.cfg, err = filepath.Abs(d.dir) - if err != nil { - log.Fatal(err) - } + if err := os.MkdirAll("testdata/gitaly-libexec", 0755); err != nil { + log.Fatal(err) + } + config.Config.BinDir, err = filepath.Abs("testdata/gitaly-libexec") + if err != nil { + log.Fatal(err) } for _, f := range []func() error{ -- GitLab