Merge branch 'structured-logging' into 'master'v7.0.0

Switch to structured logging

See merge request gitlab-org/gitlab-shell!193

17 files changed, 323 insertions, 79 deletions

diff --git a/CHANGELOG b/CHANGELOG
index 11ff00a..3adafb5 100644
--- a/CHANGELOG
+++ b/CHANGELOG
@@ -1,3 +1,6 @@
+v7.0.0
+  - Switch to structured logging (!193)
+
 v6.0.4
   - Don't delete GL_REPOSITORY environment variable from post-receive hook (!191)
 
diff --git a/VERSION b/VERSION
index 1aa5e41..66ce77b 100644
--- a/VERSION
+++ b/VERSION
@@ -1 +1 @@
-6.0.4
+7.0.0
diff --git a/config.yml.example b/config.yml.example
index 0fc8300..c616254 100644
--- a/config.yml.example
+++ b/config.yml.example
@@ -42,6 +42,9 @@ auth_file: "/home/git/.ssh/authorized_keys"
 # Log level. INFO by default
 log_level: INFO
 
+# Log format. 'text' by default
+# log_format: json
+
 # Audit usernames.
 # Set to true to see real usernames in the logs instead of key ids, which is easier to follow, but
 # incurs an extra API call on every gitlab-shell command.
diff --git a/go/internal/config/config.go b/go/internal/config/config.go
index c57b4de..7d521f5 100644
--- a/go/internal/config/config.go
+++ b/go/internal/config/config.go
@@ -5,7 +5,7 @@ import (
 	"os"
 	"path"
 
-	"gopkg.in/yaml.v2"
+	yaml "gopkg.in/yaml.v2"
 )
 
 const (
@@ -14,8 +14,9 @@ const (
 )
 
 type Config struct {
-	RootDir string
-	LogFile string `yaml:"log_file"`
+	RootDir   string
+	LogFile   string `yaml:"log_file"`
+	LogFormat string `yaml:"log_format"`
 }
 
 func New() (*Config, error) {
@@ -53,5 +54,9 @@ func parseConfig(configBytes []byte, cfg *Config) error {
 		cfg.LogFile = path.Join(cfg.RootDir, cfg.LogFile)
 	}
 
+	if cfg.LogFormat == "" {
+		cfg.LogFormat = "text"
+	}
+
 	return nil
 }
diff --git a/go/internal/config/config_test.go b/go/internal/config/config_test.go
index 0ca2dab..0a5c842 100644
--- a/go/internal/config/config_test.go
+++ b/go/internal/config/config_test.go
@@ -1,28 +1,37 @@
 package config
 
 import (
+	"fmt"
 	"testing"
 )
 
 func TestConfigLogFile(t *testing.T) {
 	testRoot := "/foo/bar"
 	testCases := []struct {
-		yaml string
-		path string
+		yaml   string
+		path   string
+		format string
 	}{
-		{path: "/foo/bar/gitlab-shell.log"},
-		{yaml: "log_file: my-log.log", path: "/foo/bar/my-log.log"},
-		{yaml: "log_file: /qux/my-log.log", path: "/qux/my-log.log"},
+		{path: "/foo/bar/gitlab-shell.log", format: "text"},
+		{yaml: "log_file: my-log.log", path: "/foo/bar/my-log.log", format: "text"},
+		{yaml: "log_file: /qux/my-log.log", path: "/qux/my-log.log", format: "text"},
+		{yaml: "log_format: json", path: "/foo/bar/gitlab-shell.log", format: "json"},
 	}
 
 	for _, tc := range testCases {
-		cfg := Config{RootDir: testRoot}
-		if err := parseConfig([]byte(tc.yaml), &cfg); err != nil {
-			t.Fatalf("%q: %v", tc.yaml, err)
-		}
+		t.Run(fmt.Sprintf("yaml input: %q", tc.yaml), func(t *testing.T) {
+			cfg := Config{RootDir: testRoot}
+			if err := parseConfig([]byte(tc.yaml), &cfg); err != nil {
+				t.Fatal(err)
+			}
 
-		if cfg.LogFile != tc.path {
-			t.Fatalf("%q: expected %q, got %q", tc.yaml, tc.path, cfg.LogFile)
-		}
+			if cfg.LogFile != tc.path {
+				t.Fatalf("expected %q, got %q", tc.path, cfg.LogFile)
+			}
+
+			if cfg.LogFormat != tc.format {
+				t.Fatalf("expected %q, got %q", tc.format, cfg.LogFormat)
+			}
+		})
 	}
 }
diff --git a/go/internal/logger/logger.go b/go/internal/logger/logger.go
index 6a4f2e3..c356d43 100644
--- a/go/internal/logger/logger.go
+++ b/go/internal/logger/logger.go
@@ -3,18 +3,19 @@ package logger
 import (
 	"fmt"
 	"io"
-	"log"
+	golog "log"
 	"log/syslog"
 	"os"
 	"sync"
-	"time"
 
 	"gitlab.com/gitlab-org/gitlab-shell/go/internal/config"
+
+	log "github.com/sirupsen/logrus"
 )
 
 var (
 	logWriter       io.Writer
-	bootstrapLogger *log.Logger
+	bootstrapLogger *golog.Logger
 	pid             int
 	mutex           sync.Mutex
 	ProgName        string
@@ -28,7 +29,16 @@ func Configure(cfg *config.Config) error {
 
 	var err error
 	logWriter, err = os.OpenFile(cfg.LogFile, os.O_WRONLY|os.O_APPEND, 0)
-	return err
+	if err != nil {
+		return err
+	}
+
+	log.SetOutput(logWriter)
+	if cfg.LogFormat == "json" {
+		log.SetFormatter(&log.JSONFormatter{})
+	}
+
+	return nil
 }
 
 func logPrint(msg string, err error) {
@@ -40,10 +50,9 @@ func logPrint(msg string, err error) {
 		return
 	}
 
-	// Emulate the existing log format of gitlab-shell
-	t := time.Now().Format("2006-01-02T15:04:05.999999")
-	prefix := fmt.Sprintf("E, [%s #%d] ERROR -- : %s:", t, pid, ProgName)
-	fmt.Fprintf(logWriter, "%s %s: %v\n", prefix, msg, err)
+	log.WithError(err).WithFields(log.Fields{
+		"pid": pid,
+	}).Error(msg)
 }
 
 func Fatal(msg string, err error) {
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
diff --git a/spec/gitlab_config_spec.rb b/spec/gitlab_config_spec.rb
index 63cb2b3..a1c52a0 100644
--- a/spec/gitlab_config_spec.rb
+++ b/spec/gitlab_config_spec.rb
@@ -24,4 +24,12 @@ describe GitlabConfig do
 
     it("returns false by default") { should eq(false) }
   end
+
+  describe :log_format do
+    subject { config.log_format }
+
+    it 'returns "text" by default' do
+      should eq('text')
+    end
+  end
 end
diff --git a/spec/gitlab_keys_spec.rb b/spec/gitlab_keys_spec.rb
index b9f2f87..c4e617c 100644
--- a/spec/gitlab_keys_spec.rb
+++ b/spec/gitlab_keys_spec.rb
@@ -57,7 +57,7 @@ describe GitlabKeys do
       before { create_authorized_keys_fixture }
 
       it "should log an add-key event" do
-        $logger.should_receive(:info).with('Adding key key-741 => "ssh-rsa AAAAB3NzaDAxx2E"')
+        $logger.should_receive(:info).with("Adding key", {:key_id=>"key-741", :public_key=>"ssh-rsa AAAAB3NzaDAxx2E"})
         gitlab_keys.send :add_key
       end
 
@@ -127,8 +127,8 @@ describe GitlabKeys do
       end
 
       it "should log an add-key event" do
-        $logger.should_receive(:info).with('Adding key key-12 => "ssh-dsa ASDFASGADG"')
-        $logger.should_receive(:info).with('Adding key key-123 => "ssh-rsa GFDGDFSGSDFG"')
+        $logger.should_receive(:info).with("Adding key", key_id: 'key-12', public_key: "ssh-dsa ASDFASGADG")
+        $logger.should_receive(:info).with("Adding key", key_id: 'key-123', public_key: "ssh-rsa GFDGDFSGSDFG")
         gitlab_keys.send :batch_add_keys
       end
 
@@ -169,7 +169,7 @@ describe GitlabKeys do
       end
 
       it "should log an rm-key event" do
-        $logger.should_receive(:info).with('Removing key key-741')
+        $logger.should_receive(:info).with("Removing key", key_id: "key-741")
         gitlab_keys.send :rm_key
       end
 
@@ -266,7 +266,7 @@ describe GitlabKeys do
     it 'should log a warning on unknown commands' do
       gitlab_keys = build_gitlab_keys('nooope')
       gitlab_keys.stub(puts: nil)
-      $logger.should_receive(:warn).with('Attempt to execute invalid gitlab-keys command "nooope".')
+      $logger.should_receive(:warn).with("Attempt to execute invalid gitlab-keys command", command: '"nooope"')
       gitlab_keys.exec
     end
   end
diff --git a/spec/gitlab_logger_spec.rb b/spec/gitlab_logger_spec.rb
index 7d8df76..741ee13 100644
--- a/spec/gitlab_logger_spec.rb
+++ b/spec/gitlab_logger_spec.rb
@@ -9,3 +9,107 @@ describe :convert_log_level do
     should eq(Logger::INFO)
   end
 end
+
+describe GitlabLogger do
+  subject { described_class.new(level, '/dev/null', format) }
+  let(:format) { 'text' }
+  let(:output) { StringIO.new }
+  let(:level) { Logger::INFO }
+  let(:time) { Time.at(123_456_789).utc } # '1973-11-29T21:33:09+00:00'
+  let(:pid) { 1234 }
+
+  before do
+    allow(subject).to receive(:log_file).and_return(output)
+    allow(subject).to receive(:time_now).and_return(time)
+    allow(subject).to receive(:pid).and_return(pid)
+  end
+
+  def first_line
+    output.string.lines.first.chomp
+  end
+
+  describe 'field sorting' do
+    it 'sorts fields, except time, level, msg' do
+      # Intentionally put 'foo' before 'baz' to see the effect of sorting
+      subject.info('hello world', foo: 'bar', baz: 'qux')
+
+      expect(first_line).to eq('time="1973-11-29T21:33:09+00:00" level=info msg="hello world" baz=qux foo=bar pid=1234')
+    end
+  end
+
+  describe '#info' do
+    context 'when the log level is too high' do
+      let(:level) { Logger::ERROR }
+
+      it 'does nothing' do
+        subject.info('hello world')
+
+        expect(output.string).to eq('')
+      end
+    end
+
+    it 'logs data' do
+      subject.info('hello world', foo: 'bar')
+
+      expect(first_line).to eq('time="1973-11-29T21:33:09+00:00" level=info msg="hello world" foo=bar pid=1234')
+    end
+  end
+
+  describe '#warn' do
+    context 'when the log level is too high' do
+      let(:level) { Logger::ERROR }
+
+      it 'does nothing' do
+        subject.warn('hello world')
+
+        expect(output.string).to eq('')
+      end
+    end
+
+    it 'logs data' do
+      subject.warn('hello world', foo: 'bar')
+
+      expect(first_line).to eq('time="1973-11-29T21:33:09+00:00" level=warn msg="hello world" foo=bar pid=1234')
+    end
+  end
+
+  describe '#debug' do
+    it 'does nothing' do
+      subject.debug('hello world')
+
+      expect(output.string).to eq('')
+    end
+
+    context 'when the log level is low enough' do
+      let(:level) { Logger::DEBUG }
+
+      it 'logs data' do
+        subject.debug('hello world', foo: 'bar')
+
+        expect(first_line).to eq('time="1973-11-29T21:33:09+00:00" level=debug msg="hello world" foo=bar pid=1234')
+      end
+    end
+  end
+
+  describe 'json logging' do
+    let(:format) { 'json' }
+
+    it 'writes valid JSON data' do
+      subject.info('hello world', foo: 'bar')
+
+      expect(JSON.parse(first_line)).to eq(
+        'foo' => 'bar',
+        'level' => 'info',
+        'msg' => 'hello world',
+        'pid' => 1234,
+        'time' => '1973-11-29T21:33:09+00:00'
+      )
+    end
+
+    it 'handles non-UTF8 string values' do
+      subject.info("hello\x80world")
+
+      expect(JSON.parse(first_line)).to include('msg' => '"hello\x80world"')
+    end
+  end
+end
diff --git a/spec/gitlab_metrics_spec.rb b/spec/gitlab_metrics_spec.rb
index 07be670..024a85a 100644
--- a/spec/gitlab_metrics_spec.rb
+++ b/spec/gitlab_metrics_spec.rb
@@ -11,7 +11,7 @@ describe GitlabMetrics do
 
     it 'writes the metrics data to a log file' do
       expect(described_class.logger).to receive(:debug).
-        with(/metrics: name=\"foo\" wall_time=\d+ cpu_time=\d+/)
+        with('metrics', a_metrics_log_message('foo'))
 
       described_class.measure('foo') { 10 }
     end
@@ -24,3 +24,13 @@ describe GitlabMetrics do
     end
   end
 end
+
+RSpec::Matchers.define :a_metrics_log_message do |x|
+  match do |actual|
+    [
+      actual.fetch(:name) == x,
+      actual.fetch(:wall_time).is_a?(Numeric),
+      actual.fetch(:cpu_time).is_a?(Numeric),
+    ].all?
+  end
+end
diff --git a/spec/gitlab_shell_spec.rb b/spec/gitlab_shell_spec.rb
index a71e2d0..82db0cf 100644
--- a/spec/gitlab_shell_spec.rb
+++ b/spec/gitlab_shell_spec.rb
@@ -160,15 +160,14 @@ describe GitlabShell do
       end
 
       it "should log the command execution" do
-        message = "gitlab-shell: executing git command "
-        message << "<git-upload-pack #{repo_path}> "
-        message << "for user with key #{key_id}."
-        $logger.should_receive(:info).with(message)
+        message = "executing git command"
+        user_string = "user with key #{key_id}"
+        $logger.should_receive(:info).with(message, command: "git-upload-pack #{repo_path}", user: user_string)
       end
 
       it "should use usernames if configured to do so" do
         GitlabConfig.any_instance.stub(audit_usernames: true)
-        $logger.should_receive(:info).with(/for John Doe/)
+        $logger.should_receive(:info).with("executing git command", hash_including(user: 'John Doe'))
       end
     end
 
@@ -196,15 +195,14 @@ describe GitlabShell do
       end
 
       it "should log the command execution" do
-        message = "gitlab-shell: executing git command "
-        message << "<gitaly-upload-pack unix:gitaly.socket #{gitaly_message}> "
-        message << "for user with key #{key_id}."
-        $logger.should_receive(:info).with(message)
+        message = "executing git command"
+        user_string = "user with key #{key_id}"
+        $logger.should_receive(:info).with(message, command: "gitaly-upload-pack unix:gitaly.socket #{gitaly_message}", user: user_string)
       end
 
       it "should use usernames if configured to do so" do
         GitlabConfig.any_instance.stub(audit_usernames: true)
-        $logger.should_receive(:info) { |msg| msg.should =~ /for John Doe/ }
+        $logger.should_receive(:info).with("executing git command", hash_including(user: 'John Doe'))
       end
     end
 
@@ -221,10 +219,9 @@ describe GitlabShell do
       end
 
       it "should log the command execution" do
-        message = "gitlab-shell: executing git command "
-        message << "<git-receive-pack #{repo_path}> "
-        message << "for user with key #{key_id}."
-        $logger.should_receive(:info).with(message)
+        message = "executing git command"
+        user_string = "user with key #{key_id}"
+        $logger.should_receive(:info).with(message, command: "git-receive-pack #{repo_path}", user: user_string)
       end
     end
 
@@ -244,15 +241,14 @@ describe GitlabShell do
       end
 
       it "should log the command execution" do
-        message = "gitlab-shell: executing git command "
-        message << "<gitaly-receive-pack unix:gitaly.socket #{gitaly_message}> "
-        message << "for user with key #{key_id}."
-        $logger.should_receive(:info).with(message)
+        message = "executing git command"
+        user_string = "user with key #{key_id}"
+        $logger.should_receive(:info).with(message, command: "gitaly-receive-pack unix:gitaly.socket #{gitaly_message}", user: user_string)
       end
 
       it "should use usernames if configured to do so" do
         GitlabConfig.any_instance.stub(audit_usernames: true)
-        $logger.should_receive(:info).with(/for John Doe/)
+        $logger.should_receive(:info).with("executing git command", hash_including(user: 'John Doe'))
       end
     end
 
@@ -269,8 +265,9 @@ describe GitlabShell do
       end
 
       it "should log the attempt" do
-        message = "gitlab-shell: Attempt to execute disallowed command <arbitrary command> by user with key #{key_id}."
-        $logger.should_receive(:warn).with(message)
+        message = 'Denied disallowed command'
+        user_string = "user with key #{key_id}"
+        $logger.should_receive(:warn).with(message, command: 'arbitrary command', user: user_string)
       end
     end
 
@@ -356,9 +353,9 @@ describe GitlabShell do
                   gl_username: nil,
                   repository_path: nil,
                   gitaly: nil))
-        message = "gitlab-shell: Access denied for git command <git-upload-pack gitlab-ci.git> "
-        message << "by user with key #{key_id}."
-        $logger.should_receive(:warn).with(message)
+        message = 'Access denied'
+        user_string = "user with key #{key_id}"
+        $logger.should_receive(:warn).with(message, command: 'git-upload-pack gitlab-ci.git', user: user_string)
       end
     end
 
@@ -450,8 +447,10 @@ describe GitlabShell do
         end
 
         it "writes an entry on the log" do
+          message = 'git trace log path must be absolute, ignoring'
+
           expect($logger).to receive(:warn).
-            with("gitlab-shell: is configured to trace git commands with #{git_trace_log_file.inspect} but an absolute path needs to be provided")
+            with(message, git_trace_log_file: git_trace_log_file)
 
           Kernel.should_receive(:exec).with(env, [1, 2], exec_options).once
           shell.send :exec_cmd, [1, 2]
@@ -474,8 +473,11 @@ describe GitlabShell do
         end
 
         it "writes an entry on the log" do
+          message = 'Failed to open git trace log file'
+          error = 'Permission denied'
+
           expect($logger).to receive(:warn).
-            with("gitlab-shell: is configured to trace git commands with #{git_trace_log_file.inspect} but it's not possible to write in that path Permission denied")
+            with(message, git_trace_log_file: git_trace_log_file, error: error)
 
           Kernel.should_receive(:exec).with(env, [1, 2], exec_options).once
           shell.send :exec_cmd, [1, 2]