Add JSON request logging for gitaly-ruby

7 files changed, 34 insertions, 3 deletions

diff --git a/.gitignore b/.gitignore
index 7e0621407..ba024eabd 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/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
diff --git a/doc/logging.md b/doc/logging.md
index 88250be7c..da6d9705e 100644
--- a/doc/logging.md
+++ b/doc/logging.md
@@ -22,6 +22,8 @@ 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 +39,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
@@ -50,6 +58,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
diff --git a/internal/testhelper/testhelper.go b/internal/testhelper/testhelper.go
index 198172034..fe6b94030 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()},
 		}
diff --git a/ruby/Gemfile b/ruby/Gemfile
index 200927770..bc2cd390e 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 4348ac753..57f7323a2 100644
--- a/ruby/Gemfile.lock
+++ b/ruby/Gemfile.lock
@@ -62,7 +62,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)
@@ -201,7 +201,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