Switch to structured logging

6 files changed, 114 insertions, 23 deletions

diff --git a/lib/gitlab_config.rb b/lib/gitlab_config.rb
index e999a83..7645989 100644
--- a/lib/gitlab_config.rb
+++ b/lib/gitlab_config.rb
@@ -42,6 +42,10 @@ class GitlabConfig
     @config['log_level'] ||= 'INFO'
   end
 
+  def log_format
+    @config['log_format'] ||= 'text'
+  end
+
   def audit_usernames
     @config['audit_usernames'] ||= false
   end
diff --git a/lib/gitlab_keys.rb b/lib/gitlab_keys.rb
index 9c38fc5..30444c3 100644
--- a/lib/gitlab_keys.rb
+++ b/lib/gitlab_keys.rb
@@ -53,7 +53,7 @@ class GitlabKeys # rubocop:disable Metrics/ClassLength
       when 'check-permissions'
         check_permissions
       else
-        $logger.warn "Attempt to execute invalid gitlab-keys command #{@command.inspect}."
+        $logger.warn('Attempt to execute invalid gitlab-keys command', command: @command.inspect)
         puts 'not allowed'
         false
       end
@@ -64,7 +64,7 @@ class GitlabKeys # rubocop:disable Metrics/ClassLength
 
   def add_key
     lock do
-      $logger.info "Adding key #{@key_id} => #{@key.inspect}"
+      $logger.info('Adding key', key_id: @key_id, public_key: @key)
       auth_line = self.class.key_line(@key_id, @key)
       open_auth_file('a') { |file| file.puts(auth_line) }
     end
@@ -102,7 +102,7 @@ class GitlabKeys # rubocop:disable Metrics/ClassLength
           tokens = input.strip.split("\t")
           abort("#{$0}: invalid input #{input.inspect}") unless tokens.count == 2
           key_id, public_key = tokens
-          $logger.info "Adding key #{key_id} => #{public_key.inspect}"
+          $logger.info('Adding key', key_id: key_id, public_key: public_key)
           file.puts(self.class.key_line(key_id, public_key))
         end
       end
@@ -116,7 +116,7 @@ class GitlabKeys # rubocop:disable Metrics/ClassLength
 
   def rm_key
     lock do
-      $logger.info "Removing key #{@key_id}"
+      $logger.info('Removing key', key_id: @key_id)
       open_auth_file('r+') do |f|
         while line = f.gets # rubocop:disable Style/AssignmentInCondition
           next unless line.start_with?("command=\"#{self.class.command(@key_id)}\"")
diff --git a/lib/gitlab_logger.rb b/lib/gitlab_logger.rb
index 872d3ed..cdca25b 100644
--- a/lib/gitlab_logger.rb
+++ b/lib/gitlab_logger.rb
@@ -1,4 +1,6 @@
+require 'json'
 require 'logger'
+require 'time'
 
 require_relative 'gitlab_config'
 
@@ -10,7 +12,97 @@ rescue NameError
   Logger::INFO
 end
 
+class GitlabLogger
+  # Emulate the quoting logic of logrus
+  # https://github.com/sirupsen/logrus/blob/v1.0.5/text_formatter.go#L143-L156
+  SHOULD_QUOTE = /[^a-zA-Z0-9\-._\/@^+]/
+
+  LEVELS = {
+    Logger::INFO => 'info'.freeze,
+    Logger::DEBUG => 'debug'.freeze,
+    Logger::WARN => 'warn'.freeze
+  }.freeze
+
+  def initialize(level, path, log_format)
+    @level = level
+    @log_file = File.open(path, 'ab')
+    @log_format = log_format
+  end
+
+  def info(message, data = {})
+    log_at(Logger::INFO, message, data)
+  end
+
+  def debug(message, data = {})
+    log_at(Logger::DEBUG, message, data)
+  end
+
+  def warn(message, data = {})
+    log_at(Logger::WARN, message, data)
+  end
+
+  private
+
+  attr_reader :log_file, :log_format
+
+  def log_at(level, message, data)
+    return unless @level <= level
+
+    data[:pid] = pid
+    data[:level] = LEVELS[level]
+    data[:msg] = message
+
+    # Use RFC3339 to match logrus in the Go parts of gitlab-shell
+    data[:time] = time_now.to_datetime.rfc3339
+
+    case log_format
+    when 'json'
+      log_file.puts format_json(data)
+    else
+      log_file.puts format_text(data)
+    end
+  end
+
+  def pid
+    Process.pid
+  end
+
+  def time_now
+    Time.now
+  end
+
+  def format_text(data)
+    # We start the line with these fields to match the behavior of logrus
+    result = [
+      format_key_value(:time, data.delete(:time)),
+      format_key_value(:level, data.delete(:level)),
+      format_key_value(:msg, data.delete(:msg))
+    ]
+
+    data.sort.each { |k, v| result << format_key_value(k, v) }
+    result.join(' ')
+  end
+
+  def format_key_value(key, value)
+    value_string = value.to_s
+    value_string = value_string.inspect if SHOULD_QUOTE =~ value_string
+
+    "#{key}=#{value_string}"
+  end
+
+  def format_json(data)
+    data.each do |key, value|
+      next unless value.is_a?(String)
+
+      value = value.dup.force_encoding('utf-8')
+      value = value.inspect unless value.valid_encoding?
+      data[key] = value.freeze
+    end
+
+    data.to_json
+  end
+end
+
 config = GitlabConfig.new
 
-$logger = Logger.new(config.log_file)
-$logger.level = convert_log_level(config.log_level)
+$logger = GitlabLogger.new(convert_log_level(config.log_level), config.log_file, config.log_format)
diff --git a/lib/gitlab_metrics.rb b/lib/gitlab_metrics.rb
index 413b799..917a489 100644
--- a/lib/gitlab_metrics.rb
+++ b/lib/gitlab_metrics.rb
@@ -1,4 +1,3 @@
-require 'logger'
 require_relative 'gitlab_config'
 require_relative 'gitlab_logger'
 
@@ -53,7 +52,7 @@ module GitlabMetrics
     real_time = System.monotonic_time - start_real
     cpu_time = System.cpu_time - start_cpu
 
-    logger.debug("metrics: name=#{name.inspect} wall_time=#{real_time} cpu_time=#{cpu_time}")
+    logger.debug('metrics', name: name, wall_time: real_time, cpu_time: cpu_time)
 
     retval
   end
diff --git a/lib/gitlab_net.rb b/lib/gitlab_net.rb
index a5736d6..c93cf9a 100644
--- a/lib/gitlab_net.rb
+++ b/lib/gitlab_net.rb
@@ -190,7 +190,7 @@ class GitlabNet # rubocop:disable Metrics/ClassLength
   end
 
   def request(method, url, params = {}, options = {})
-    $logger.debug "Performing #{method.to_s.upcase} #{url}"
+    $logger.debug('Performing request', method: method.to_s.upcase, url: url)
 
     uri = URI.parse(url)
 
@@ -201,18 +201,16 @@ class GitlabNet # rubocop:disable Metrics/ClassLength
       start_time = Time.new
       response = http.start { http.request(request) }
     rescue => e
-      $logger.warn "Failed to connect to internal API <#{method.to_s.upcase} #{url}>: #{e.inspect}"
+      $logger.warn('Failed to connect to internal API', method: method.to_s.upcase, url: url, error: e)
       raise ApiUnreachableError
     ensure
-      $logger.info do
-        sprintf('%s %s %0.5f', method.to_s.upcase, url, Time.new - start_time) # rubocop:disable Style/FormatString
-      end
+      $logger.info('finished HTTP request', method: method.to_s.upcase, url: url, duration: Time.new - start_time)
     end
 
     if response.code == "200"
-      $logger.debug "Received response #{response.code} => <#{response.body}>."
+      $logger.debug('Received response', code: response.code, body: response.body)
     else
-      $logger.error "API call <#{method.to_s.upcase} #{url}> failed: #{response.code} => <#{response.body}>."
+      $logger.error('API call failed', method: method.to_s.upcase, url: url, code: response.code, body: response.body)
     end
 
     response
diff --git a/lib/gitlab_shell.rb b/lib/gitlab_shell.rb
index 01b6af4..8002f0b 100644
--- a/lib/gitlab_shell.rb
+++ b/lib/gitlab_shell.rb
@@ -48,14 +48,12 @@ class GitlabShell # rubocop:disable Metrics/ClassLength
     $stderr.puts "GitLab: Failed to authorize your Git request: internal API unreachable"
     false
   rescue AccessDeniedError => ex
-    message = "gitlab-shell: Access denied for git command <#{origin_cmd}> by #{log_username}."
-    $logger.warn message
+    $logger.warn('Access denied', command: origin_cmd, user: log_username)
 
     $stderr.puts "GitLab: #{ex.message}"
     false
   rescue DisallowedCommandError
-    message = "gitlab-shell: Attempt to execute disallowed command <#{origin_cmd}> by #{log_username}."
-    $logger.warn message
+    $logger.warn('Denied disallowed command', command: origin_cmd, user: log_username)
 
     $stderr.puts "GitLab: Disallowed command"
     false
@@ -117,7 +115,7 @@ class GitlabShell # rubocop:disable Metrics/ClassLength
 
     if @command == 'git-lfs-authenticate'
       GitlabMetrics.measure('lfs-authenticate') do
-        $logger.info "gitlab-shell: Processing LFS authentication for #{log_username}."
+        $logger.info('Processing LFS authentication', user: log_username)
         lfs_authenticate
       end
       return
@@ -144,7 +142,7 @@ class GitlabShell # rubocop:disable Metrics/ClassLength
     end
 
     args_string = [File.basename(executable), *args].join(' ')
-    $logger.info "gitlab-shell: executing git command <#{args_string}> for #{log_username}."
+    $logger.info('executing git command', command: args_string, user: log_username)
     exec_cmd(executable, *args)
   end
 
@@ -253,7 +251,7 @@ class GitlabShell # rubocop:disable Metrics/ClassLength
     return false unless @config.git_trace_log_file
 
     if Pathname(@config.git_trace_log_file).relative?
-      $logger.warn "gitlab-shell: is configured to trace git commands with #{@config.git_trace_log_file.inspect} but an absolute path needs to be provided"
+      $logger.warn('git trace log path must be absolute, ignoring', git_trace_log_file: @config.git_trace_log_file)
       return false
     end
 
@@ -261,7 +259,7 @@ class GitlabShell # rubocop:disable Metrics/ClassLength
       File.open(@config.git_trace_log_file, 'a') { nil }
       return true
     rescue => ex
-      $logger.warn "gitlab-shell: is configured to trace git commands with #{@config.git_trace_log_file.inspect} but it's not possible to write in that path #{ex.message}"
+      $logger.warn('Failed to open git trace log file', git_trace_log_file: @config.git_trace_log_file, error: ex.to_s)
       return false
     end
   end