Commit 9b9ada10 authored by Douwe Maan's avatar Douwe Maan

Merge branch 'structured-logging' into 'master'

Switch to structured logging

See merge request gitlab-org/gitlab-shell!193
parents 355e70e0 b8a5e521
v7.0.0
- Switch to structured logging (!193)
v6.0.4
- Don't delete GL_REPOSITORY environment variable from post-receive hook (!191)
......
......@@ -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.
......
......@@ -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
}
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)
}
})
}
}
......@@ -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) {
......
......@@ -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
......
......@@ -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)}\"")
......
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)
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
......
......@@ -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
......
......@@ -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
......
......@@ -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
......@@ -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
......
......@@ -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
......@@ -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
......@@ -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]
......
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