diff options
author | Douwe Maan <douwe@gitlab.com> | 2018-03-19 11:58:59 +0000 |
---|---|---|
committer | Douwe Maan <douwe@gitlab.com> | 2018-03-19 11:58:59 +0000 |
commit | 9b9ada1013bd91e316c2e85b7c0f0ef8cb02f688 (patch) | |
tree | 30833503feb797f8610b21f2475c04e959b0ebac | |
parent | 355e70e08b9180456ef57fb79a2c3b5654f85479 (diff) | |
parent | b8a5e52193b7d02de4802b589e098bbbfa0ec425 (diff) | |
download | gitlab-shell-9b9ada1013bd91e316c2e85b7c0f0ef8cb02f688.tar.gz |
Merge branch 'structured-logging' into 'master'v7.0.0
Switch to structured logging
See merge request gitlab-org/gitlab-shell!193
-rw-r--r-- | CHANGELOG | 3 | ||||
-rw-r--r-- | VERSION | 2 | ||||
-rw-r--r-- | config.yml.example | 3 | ||||
-rw-r--r-- | go/internal/config/config.go | 11 | ||||
-rw-r--r-- | go/internal/config/config_test.go | 33 | ||||
-rw-r--r-- | go/internal/logger/logger.go | 25 | ||||
-rw-r--r-- | lib/gitlab_config.rb | 4 | ||||
-rw-r--r-- | lib/gitlab_keys.rb | 8 | ||||
-rw-r--r-- | lib/gitlab_logger.rb | 96 | ||||
-rw-r--r-- | lib/gitlab_metrics.rb | 3 | ||||
-rw-r--r-- | lib/gitlab_net.rb | 12 | ||||
-rw-r--r-- | lib/gitlab_shell.rb | 14 | ||||
-rw-r--r-- | spec/gitlab_config_spec.rb | 8 | ||||
-rw-r--r-- | spec/gitlab_keys_spec.rb | 10 | ||||
-rw-r--r-- | spec/gitlab_logger_spec.rb | 104 | ||||
-rw-r--r-- | spec/gitlab_metrics_spec.rb | 12 | ||||
-rw-r--r-- | spec/gitlab_shell_spec.rb | 54 |
17 files changed, 323 insertions, 79 deletions
@@ -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) @@ -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] |