Commit b8a5e521 authored by Jacob Vosmaer (GitLab)'s avatar Jacob Vosmaer (GitLab) Committed by Douwe Maan

Switch to structured logging

parent 355e70e0
v7.0.0
- Switch to structured logging (!193)
v6.0.4 v6.0.4
- Don't delete GL_REPOSITORY environment variable from post-receive hook (!191) - Don't delete GL_REPOSITORY environment variable from post-receive hook (!191)
......
...@@ -42,6 +42,9 @@ auth_file: "/home/git/.ssh/authorized_keys" ...@@ -42,6 +42,9 @@ auth_file: "/home/git/.ssh/authorized_keys"
# Log level. INFO by default # Log level. INFO by default
log_level: INFO log_level: INFO
# Log format. 'text' by default
# log_format: json
# Audit usernames. # Audit usernames.
# Set to true to see real usernames in the logs instead of key ids, which is easier to follow, but # 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. # incurs an extra API call on every gitlab-shell command.
......
...@@ -5,7 +5,7 @@ import ( ...@@ -5,7 +5,7 @@ import (
"os" "os"
"path" "path"
"gopkg.in/yaml.v2" yaml "gopkg.in/yaml.v2"
) )
const ( const (
...@@ -14,8 +14,9 @@ const ( ...@@ -14,8 +14,9 @@ const (
) )
type Config struct { type Config struct {
RootDir string RootDir string
LogFile string `yaml:"log_file"` LogFile string `yaml:"log_file"`
LogFormat string `yaml:"log_format"`
} }
func New() (*Config, error) { func New() (*Config, error) {
...@@ -53,5 +54,9 @@ func parseConfig(configBytes []byte, cfg *Config) error { ...@@ -53,5 +54,9 @@ func parseConfig(configBytes []byte, cfg *Config) error {
cfg.LogFile = path.Join(cfg.RootDir, cfg.LogFile) cfg.LogFile = path.Join(cfg.RootDir, cfg.LogFile)
} }
if cfg.LogFormat == "" {
cfg.LogFormat = "text"
}
return nil return nil
} }
package config package config
import ( import (
"fmt"
"testing" "testing"
) )
func TestConfigLogFile(t *testing.T) { func TestConfigLogFile(t *testing.T) {
testRoot := "/foo/bar" testRoot := "/foo/bar"
testCases := []struct { testCases := []struct {
yaml string yaml string
path string path string
format string
}{ }{
{path: "/foo/bar/gitlab-shell.log"}, {path: "/foo/bar/gitlab-shell.log", format: "text"},
{yaml: "log_file: my-log.log", path: "/foo/bar/my-log.log"}, {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"}, {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 { for _, tc := range testCases {
cfg := Config{RootDir: testRoot} t.Run(fmt.Sprintf("yaml input: %q", tc.yaml), func(t *testing.T) {
if err := parseConfig([]byte(tc.yaml), &cfg); err != nil { cfg := Config{RootDir: testRoot}
t.Fatalf("%q: %v", tc.yaml, err) if err := parseConfig([]byte(tc.yaml), &cfg); err != nil {
} t.Fatal(err)
}
if cfg.LogFile != tc.path { if cfg.LogFile != tc.path {
t.Fatalf("%q: expected %q, got %q", tc.yaml, tc.path, cfg.LogFile) 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)
}
})
} }
} }
...@@ -3,18 +3,19 @@ package logger ...@@ -3,18 +3,19 @@ package logger
import ( import (
"fmt" "fmt"
"io" "io"
"log" golog "log"
"log/syslog" "log/syslog"
"os" "os"
"sync" "sync"
"time"
"gitlab.com/gitlab-org/gitlab-shell/go/internal/config" "gitlab.com/gitlab-org/gitlab-shell/go/internal/config"
log "github.com/sirupsen/logrus"
) )
var ( var (
logWriter io.Writer logWriter io.Writer
bootstrapLogger *log.Logger bootstrapLogger *golog.Logger
pid int pid int
mutex sync.Mutex mutex sync.Mutex
ProgName string ProgName string
...@@ -28,7 +29,16 @@ func Configure(cfg *config.Config) error { ...@@ -28,7 +29,16 @@ func Configure(cfg *config.Config) error {
var err error var err error
logWriter, err = os.OpenFile(cfg.LogFile, os.O_WRONLY|os.O_APPEND, 0) 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) { func logPrint(msg string, err error) {
...@@ -40,10 +50,9 @@ func logPrint(msg string, err error) { ...@@ -40,10 +50,9 @@ func logPrint(msg string, err error) {
return return
} }
// Emulate the existing log format of gitlab-shell log.WithError(err).WithFields(log.Fields{
t := time.Now().Format("2006-01-02T15:04:05.999999") "pid": pid,
prefix := fmt.Sprintf("E, [%s #%d] ERROR -- : %s:", t, pid, ProgName) }).Error(msg)
fmt.Fprintf(logWriter, "%s %s: %v\n", prefix, msg, err)
} }
func Fatal(msg string, err error) { func Fatal(msg string, err error) {
......
...@@ -42,6 +42,10 @@ class GitlabConfig ...@@ -42,6 +42,10 @@ class GitlabConfig
@config['log_level'] ||= 'INFO' @config['log_level'] ||= 'INFO'
end end
def log_format
@config['log_format'] ||= 'text'
end
def audit_usernames def audit_usernames
@config['audit_usernames'] ||= false @config['audit_usernames'] ||= false
end end
......
...@@ -53,7 +53,7 @@ class GitlabKeys # rubocop:disable Metrics/ClassLength ...@@ -53,7 +53,7 @@ class GitlabKeys # rubocop:disable Metrics/ClassLength
when 'check-permissions' when 'check-permissions'
check_permissions check_permissions
else 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' puts 'not allowed'
false false
end end
...@@ -64,7 +64,7 @@ class GitlabKeys # rubocop:disable Metrics/ClassLength ...@@ -64,7 +64,7 @@ class GitlabKeys # rubocop:disable Metrics/ClassLength
def add_key def add_key
lock do 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) auth_line = self.class.key_line(@key_id, @key)
open_auth_file('a') { |file| file.puts(auth_line) } open_auth_file('a') { |file| file.puts(auth_line) }
end end
...@@ -102,7 +102,7 @@ class GitlabKeys # rubocop:disable Metrics/ClassLength ...@@ -102,7 +102,7 @@ class GitlabKeys # rubocop:disable Metrics/ClassLength
tokens = input.strip.split("\t") tokens = input.strip.split("\t")
abort("#{$0}: invalid input #{input.inspect}") unless tokens.count == 2 abort("#{$0}: invalid input #{input.inspect}") unless tokens.count == 2
key_id, public_key = tokens 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)) file.puts(self.class.key_line(key_id, public_key))
end end
end end
...@@ -116,7 +116,7 @@ class GitlabKeys # rubocop:disable Metrics/ClassLength ...@@ -116,7 +116,7 @@ class GitlabKeys # rubocop:disable Metrics/ClassLength
def rm_key def rm_key
lock do lock do
$logger.info "Removing key #{@key_id}" $logger.info('Removing key', key_id: @key_id)
open_auth_file('r+') do |f| open_auth_file('r+') do |f|
while line = f.gets # rubocop:disable Style/AssignmentInCondition while line = f.gets # rubocop:disable Style/AssignmentInCondition
next unless line.start_with?("command=\"#{self.class.command(@key_id)}\"") next unless line.start_with?("command=\"#{self.class.command(@key_id)}\"")
......
require 'json'
require 'logger' require 'logger'
require 'time'
require_relative 'gitlab_config' require_relative 'gitlab_config'
...@@ -10,7 +12,97 @@ rescue NameError ...@@ -10,7 +12,97 @@ rescue NameError
Logger::INFO Logger::INFO
end 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 config = GitlabConfig.new
$logger = Logger.new(config.log_file) $logger = GitlabLogger.new(convert_log_level(config.log_level), config.log_file, config.log_format)
$logger.level = convert_log_level(config.log_level)
require 'logger'
require_relative 'gitlab_config' require_relative 'gitlab_config'
require_relative 'gitlab_logger' require_relative 'gitlab_logger'
...@@ -53,7 +52,7 @@ module GitlabMetrics ...@@ -53,7 +52,7 @@ module GitlabMetrics
real_time = System.monotonic_time - start_real real_time = System.monotonic_time - start_real
cpu_time = System.cpu_time - start_cpu 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 retval
end end
......
...@@ -190,7 +190,7 @@ class GitlabNet # rubocop:disable Metrics/ClassLength ...@@ -190,7 +190,7 @@ class GitlabNet # rubocop:disable Metrics/ClassLength
end end
def request(method, url, params = {}, options = {}) 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) uri = URI.parse(url)
...@@ -201,18 +201,16 @@ class GitlabNet # rubocop:disable Metrics/ClassLength ...@@ -201,18 +201,16 @@ class GitlabNet # rubocop:disable Metrics/ClassLength
start_time = Time.new start_time = Time.new
response = http.start { http.request(request) } response = http.start { http.request(request) }
rescue => e 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 raise ApiUnreachableError
ensure ensure
$logger.info do $logger.info('finished HTTP request', method: method.to_s.upcase, url: url, duration: Time.new - start_time)
sprintf('%s %s %0.5f', method.to_s.upcase, url, Time.new - start_time) # rubocop:disable Style/FormatString
end
end end
if response.code == "200" if response.code == "200"
$logger.debug "Received response #{response.code} => <#{response.body}>." $logger.debug('Received response', code: response.code, body: response.body)
else 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 end
response response
......
...@@ -48,14 +48,12 @@ class GitlabShell # rubocop:disable Metrics/ClassLength ...@@ -48,14 +48,12 @@ class GitlabShell # rubocop:disable Metrics/ClassLength
$stderr.puts "GitLab: Failed to authorize your Git request: internal API unreachable" $stderr.puts "GitLab: Failed to authorize your Git request: internal API unreachable"
false false
rescue AccessDeniedError => ex rescue AccessDeniedError => ex
message = "gitlab-shell: Access denied for git command <#{origin_cmd}> by #{log_username}." $logger.warn('Access denied', command: origin_cmd, user: log_username)
$logger.warn message
$stderr.puts "GitLab: #{ex.message}" $stderr.puts "GitLab: #{ex.message}"
false false
rescue DisallowedCommandError rescue DisallowedCommandError
message = "gitlab-shell: Attempt to execute disallowed command <#{origin_cmd}> by #{log_username}." $logger.warn('Denied disallowed command', command: origin_cmd, user: log_username)
$logger.warn message
$stderr.puts "GitLab: Disallowed command" $stderr.puts "GitLab: Disallowed command"
false false
...@@ -117,7 +115,7 @@ class GitlabShell # rubocop:disable Metrics/ClassLength ...@@ -117,7 +115,7 @@ class GitlabShell # rubocop:disable Metrics/ClassLength
if @command == 'git-lfs-authenticate' if @command == 'git-lfs-authenticate'
GitlabMetrics.measure('lfs-authenticate') do 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 lfs_authenticate
end end
return return
...@@ -144,7 +142,7 @@ class GitlabShell # rubocop:disable Metrics/ClassLength ...@@ -144,7 +142,7 @@ class GitlabShell # rubocop:disable Metrics/ClassLength
end end
args_string = [File.basename(executable), *args].join(' ') 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) exec_cmd(executable, *args)
end end
...@@ -253,7 +251,7 @@ class GitlabShell # rubocop:disable Metrics/ClassLength ...@@ -253,7 +251,7 @@ class GitlabShell # rubocop:disable Metrics/ClassLength
return false unless @config.git_trace_log_file return false unless @config.git_trace_log_file
if Pathname(@config.git_trace_log_file).relative? 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 return false
end end
...@@ -261,7 +259,7 @@ class GitlabShell # rubocop:disable Metrics/ClassLength ...@@ -261,7 +259,7 @@ class GitlabShell # rubocop:disable Metrics/ClassLength
File.open(@config.git_trace_log_file, 'a') { nil } File.open(@config.git_trace_log_file, 'a') { nil }
return true return true
rescue => ex 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 return false
end end
end end
......
...@@ -24,4 +24,12 @@ describe GitlabConfig do ...@@ -24,4 +24,12 @@ describe GitlabConfig do
it("returns false by default") { should eq(false) } it("returns false by default") { should eq(false) }
end end
describe :log_format do
subject { config.log_format }
it 'returns "text" by default' do
should eq('text')
end
end
end end
...@@ -57,7 +57,7 @@ describe GitlabKeys do ...@@ -57,7 +57,7 @@ describe GitlabKeys do
before { create_authorized_keys_fixture } before { create_authorized_keys_fixture }
it "should log an add-key event" do 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 gitlab_keys.send :add_key
end end
...@@ -127,8 +127,8 @@ describe GitlabKeys do ...@@ -127,8 +127,8 @@ describe GitlabKeys do
end end
it "should log an add-key event" do 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_id: 'key-12', public_key: "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-123', public_key: "ssh-rsa GFDGDFSGSDFG")
gitlab_keys.send :batch_add_keys gitlab_keys.send :batch_add_keys
end end
...@@ -169,7 +169,7 @@ describe GitlabKeys do ...@@ -169,7 +169,7 @@ describe GitlabKeys do
end end
it "should log an rm-key event" do 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 gitlab_keys.send :rm_key
end end
...@@ -266,7 +266,7 @@ describe GitlabKeys do ...@@ -266,7 +266,7 @@ describe GitlabKeys do
it 'should log a warning on unknown commands' do it 'should log a warning on unknown commands' do
gitlab_keys = build_gitlab_keys('nooope') gitlab_keys = build_gitlab_keys('nooope')
gitlab_keys.stub(puts: nil) 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 gitlab_keys.exec
end end
end end
......
...@@ -9,3 +9,107 @@ describe :convert_log_level do ...@@ -9,3 +9,107 @@ describe :convert_log_level do
should eq(Logger::INFO) should eq(Logger::INFO)
end end
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
...@@ -11,7 +11,7 @@ describe GitlabMetrics do ...@@ -11,7 +11,7 @@ describe GitlabMetrics do
it 'writes the metrics data to a log file' do it 'writes the metrics data to a log file' do
expect(described_class.logger).to receive(:debug). 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 } described_class.measure('foo') { 10 }
end end
...@@ -24,3 +24,13 @@ describe GitlabMetrics do ...@@ -24,3 +24,13 @@ describe GitlabMetrics do
end end
end 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
...@@ -160,15 +160,14 @@ describe GitlabShell do ...@@ -160,15 +160,14 @@ describe GitlabShell do
end end
it "should log the command execution" do it "should log the command execution" do
message = "gitlab-shell: executing git command " message = "executing git command"
message << "<git-upload-pack #{repo_path}> " user_string = "user with key #{key_id}"
message << "for user with key #{key_id}." $logger.should_receive(:info).with(message, command: "git-upload-pack #{repo_path}", user: user_string)
$logger.should_receive(:info).with(message)
end end
it "should use usernames if configured to do so" do it "should use usernames if configured to do so" do
GitlabConfig.any_instance.stub(audit_usernames: true) 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
end end
...@@ -196,15 +195,14 @@ describe GitlabShell do ...@@ -196,15 +195,14 @@ describe GitlabShell do
end end
it "should log the command execution" do it "should log the command execution" do
message = "gitlab-shell: executing git command " message = "executing git command"
message << "<gitaly-upload-pack unix:gitaly.socket #{gitaly_message}> " user_string = "user with key #{key_id}"
message << "for user with key #{key_id}." $logger.should_receive(:info).with(message, command: "gitaly-upload-pack unix:gitaly.socket #{gitaly_message}", user: user_string)
$logger.should_receive(:info).with(message)
end end
it "should use usernames if configured to do so" do it "should use usernames if configured to do so" do
GitlabConfig.any_instance.stub(audit_usernames: true) 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
end end
...@@ -221,10 +219,9 @@ describe GitlabShell do ...@@ -221,10 +219,9 @@ describe GitlabShell do
end end
it "should log the command execution" do it "should log the command execution" do
message = "gitlab-shell: executing git command " message = "executing git command"
message << "<git-receive-pack #{repo_path}> " user_string = "user with key #{key_id}"
message << "for user with key #{key_id}." $logger.should_receive(:info).with(message, command: "git-receive-pack #{repo_path}", user: user_string)
$logger.should_receive(:info).with(message)
end end
end end
...@@ -244,15 +241,14 @@ describe GitlabShell do ...@@ -244,15 +241,14 @@ describe GitlabShell do
end end
it "should log the command execution" do it "should log the command execution" do
message = "gitlab-shell: executing git command " message = "executing git command"
message << "<gitaly-receive-pack unix:gitaly.socket #{gitaly_message}> " user_string = "user with key #{key_id}"
message << "for user with key #{key_id}." $logger.should_receive(:info).with(message, command: "gitaly-receive-pack unix:gitaly.socket #{gitaly_message}", user: user_string)
$logger.should_receive(:info).with(message)
end end
it "should use usernames if configured to do so" do it "should use usernames if configured to do so" do
GitlabConfig.any_instance.stub(audit_usernames: true) 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
end end
...@@ -269,8 +265,9 @@ describe GitlabShell do ...@@ -269,8 +265,9 @@ describe GitlabShell do
end end
it "should log the attempt" do it "should log the attempt" do
message = "gitlab-shell: Attempt to execute disallowed command <arbitrary command> by user with key #{key_id}." message = 'Denied disallowed command'
$logger.should_receive(:warn).with(message) user_string = "user with key #{key_id}"
$logger.should_receive(:warn).with(message, command: 'arbitrary command', user: user_string)
end end
end end
...@@ -356,9 +353,9 @@ describe GitlabShell do ...@@ -356,9 +353,9 @@ describe GitlabShell do
gl_username: nil, gl_username: nil,
repository_path: nil, repository_path: nil,
gitaly: nil)) gitaly: nil))
message = "gitlab-shell: Access denied for git command <git-upload-pack gitlab-ci.git> " message = 'Access denied'
message << "by user with key #{key_id}." user_string = "user with key #{key_id}"
$logger.should_receive(:warn).with(message) $logger.should_receive(:warn).with(message, command: 'git-upload-pack gitlab-ci.git', user: user_string)
end end
end end
...@@ -450,8 +447,10 @@ describe GitlabShell do ...@@ -450,8 +447,10 @@ describe GitlabShell do
end end
it "writes an entry on the log" do it "writes an entry on the log" do
message = 'git trace log path must be absolute, ignoring'
expect($logger).to receive(:warn). 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 Kernel.should_receive(:exec).with(env, [1, 2], exec_options).once
shell.send :exec_cmd, [1, 2] shell.send :exec_cmd, [1, 2]
...@@ -474,8 +473,11 @@ describe GitlabShell do ...@@ -474,8 +473,11 @@ describe GitlabShell do
end end
it "writes an entry on the log" do it "writes an entry on the log" do
message = 'Failed to open git trace log file'
error = 'Permission denied'
expect($logger).to receive(:warn). 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 Kernel.should_receive(:exec).with(env, [1, 2], exec_options).once
shell.send :exec_cmd, [1, 2] shell.send :exec_cmd, [1, 2]
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment