Commit c3ecc40e authored by Tomasz Maczukin's avatar Tomasz Maczukin

Merge branch 'refactor-and-improve-testing-of-log-package' into 'master'

Refactor and improve testing of log package

See merge request gitlab-org/gitlab-runner!1039
parents 60236d1d d9ea00dd
......@@ -156,11 +156,12 @@ dockerfiles:
mocks: $(MOCKERY)
rm -rf ./helpers/service/mocks
find . -type f ! -path '*vendor/*' -name 'mock_*' -delete
GOPATH=$(ORIGINAL_GOPATH) mockery $(MOCKERY_FLAGS) -dir=./vendor/github.com/ayufan/golang-kardianos-service -output=./helpers/service/mocks -name='(Interface|Logger)'
GOPATH=$(ORIGINAL_GOPATH) mockery $(MOCKERY_FLAGS) -dir=./vendor/github.com/ayufan/golang-kardianos-service -output=./helpers/service/mocks -name='(Interface)'
GOPATH=$(ORIGINAL_GOPATH) mockery $(MOCKERY_FLAGS) -dir=./helpers/docker -all -inpkg
GOPATH=$(ORIGINAL_GOPATH) mockery $(MOCKERY_FLAGS) -dir=./helpers/certificate -all -inpkg
GOPATH=$(ORIGINAL_GOPATH) mockery $(MOCKERY_FLAGS) -dir=./cache -all -inpkg
GOPATH=$(ORIGINAL_GOPATH) mockery $(MOCKERY_FLAGS) -dir=./common -all -inpkg
GOPATH=$(ORIGINAL_GOPATH) mockery $(MOCKERY_FLAGS) -dir=./log -all -inpkg
GOPATH=$(ORIGINAL_GOPATH) mockery $(MOCKERY_FLAGS) -dir=./session -all -inpkg
GOPATH=$(ORIGINAL_GOPATH) mockery $(MOCKERY_FLAGS) -dir=./shells -all -inpkg
......
......@@ -664,7 +664,7 @@ func (mr *RunCommand) Execute(context *cli.Context) {
}
if mr.Syslog {
log.SetSystemLogger(svc)
log.SetSystemLogger(logrus.StandardLogger(), svc)
}
logrus.AddHook(&mr.sentryLogHook)
......
......@@ -2,17 +2,17 @@
// This comment works around https://github.com/vektra/mockery/issues/155
package mocks
package log
import mock "github.com/stretchr/testify/mock"
// Logger is an autogenerated mock type for the Logger type
type Logger struct {
// mockSystemLogger is an autogenerated mock type for the systemLogger type
type mockSystemLogger struct {
mock.Mock
}
// Error provides a mock function with given fields: v
func (_m *Logger) Error(v ...interface{}) error {
func (_m *mockSystemLogger) Error(v ...interface{}) error {
var _ca []interface{}
_ca = append(_ca, v...)
ret := _m.Called(_ca...)
......@@ -28,7 +28,7 @@ func (_m *Logger) Error(v ...interface{}) error {
}
// Errorf provides a mock function with given fields: format, a
func (_m *Logger) Errorf(format string, a ...interface{}) error {
func (_m *mockSystemLogger) Errorf(format string, a ...interface{}) error {
var _ca []interface{}
_ca = append(_ca, format)
_ca = append(_ca, a...)
......@@ -45,7 +45,7 @@ func (_m *Logger) Errorf(format string, a ...interface{}) error {
}
// Info provides a mock function with given fields: v
func (_m *Logger) Info(v ...interface{}) error {
func (_m *mockSystemLogger) Info(v ...interface{}) error {
var _ca []interface{}
_ca = append(_ca, v...)
ret := _m.Called(_ca...)
......@@ -61,7 +61,7 @@ func (_m *Logger) Info(v ...interface{}) error {
}
// Infof provides a mock function with given fields: format, a
func (_m *Logger) Infof(format string, a ...interface{}) error {
func (_m *mockSystemLogger) Infof(format string, a ...interface{}) error {
var _ca []interface{}
_ca = append(_ca, format)
_ca = append(_ca, a...)
......@@ -78,7 +78,7 @@ func (_m *Logger) Infof(format string, a ...interface{}) error {
}
// Warning provides a mock function with given fields: v
func (_m *Logger) Warning(v ...interface{}) error {
func (_m *mockSystemLogger) Warning(v ...interface{}) error {
var _ca []interface{}
_ca = append(_ca, v...)
ret := _m.Called(_ca...)
......@@ -94,7 +94,7 @@ func (_m *Logger) Warning(v ...interface{}) error {
}
// Warningf provides a mock function with given fields: format, a
func (_m *Logger) Warningf(format string, a ...interface{}) error {
func (_m *mockSystemLogger) Warningf(format string, a ...interface{}) error {
var _ca []interface{}
_ca = append(_ca, format)
_ca = append(_ca, a...)
......
// Code generated by mockery v1.0.0. DO NOT EDIT.
// This comment works around https://github.com/vektra/mockery/issues/155
package log
import mock "github.com/stretchr/testify/mock"
import service "github.com/ayufan/golang-kardianos-service"
// mockSystemService is an autogenerated mock type for the systemService type
type mockSystemService struct {
mock.Mock
}
// Install provides a mock function with given fields:
func (_m *mockSystemService) Install() error {
ret := _m.Called()
var r0 error
if rf, ok := ret.Get(0).(func() error); ok {
r0 = rf()
} else {
r0 = ret.Error(0)
}
return r0
}
// Logger provides a mock function with given fields: errs
func (_m *mockSystemService) Logger(errs chan<- error) (service.Logger, error) {
ret := _m.Called(errs)
var r0 service.Logger
if rf, ok := ret.Get(0).(func(chan<- error) service.Logger); ok {
r0 = rf(errs)
} else {
if ret.Get(0) != nil {
r0 = ret.Get(0).(service.Logger)
}
}
var r1 error
if rf, ok := ret.Get(1).(func(chan<- error) error); ok {
r1 = rf(errs)
} else {
r1 = ret.Error(1)
}
return r0, r1
}
// Restart provides a mock function with given fields:
func (_m *mockSystemService) Restart() error {
ret := _m.Called()
var r0 error
if rf, ok := ret.Get(0).(func() error); ok {
r0 = rf()
} else {
r0 = ret.Error(0)
}
return r0
}
// Run provides a mock function with given fields:
func (_m *mockSystemService) Run() error {
ret := _m.Called()
var r0 error
if rf, ok := ret.Get(0).(func() error); ok {
r0 = rf()
} else {
r0 = ret.Error(0)
}
return r0
}
// Start provides a mock function with given fields:
func (_m *mockSystemService) Start() error {
ret := _m.Called()
var r0 error
if rf, ok := ret.Get(0).(func() error); ok {
r0 = rf()
} else {
r0 = ret.Error(0)
}
return r0
}
// Status provides a mock function with given fields:
func (_m *mockSystemService) Status() error {
ret := _m.Called()
var r0 error
if rf, ok := ret.Get(0).(func() error); ok {
r0 = rf()
} else {
r0 = ret.Error(0)
}
return r0
}
// Stop provides a mock function with given fields:
func (_m *mockSystemService) Stop() error {
ret := _m.Called()
var r0 error
if rf, ok := ret.Get(0).(func() error); ok {
r0 = rf()
} else {
r0 = ret.Error(0)
}
return r0
}
// String provides a mock function with given fields:
func (_m *mockSystemService) String() string {
ret := _m.Called()
var r0 string
if rf, ok := ret.Get(0).(func() string); ok {
r0 = rf()
} else {
r0 = ret.Get(0).(string)
}
return r0
}
// SystemLogger provides a mock function with given fields: errs
func (_m *mockSystemService) SystemLogger(errs chan<- error) (service.Logger, error) {
ret := _m.Called(errs)
var r0 service.Logger
if rf, ok := ret.Get(0).(func(chan<- error) service.Logger); ok {
r0 = rf(errs)
} else {
if ret.Get(0) != nil {
r0 = ret.Get(0).(service.Logger)
}
}
var r1 error
if rf, ok := ret.Get(1).(func(chan<- error) error); ok {
r1 = rf(errs)
} else {
r1 = ret.Error(1)
}
return r0, r1
}
// Uninstall provides a mock function with given fields:
func (_m *mockSystemService) Uninstall() error {
ret := _m.Called()
var r0 error
if rf, ok := ret.Get(0).(func() error); ok {
r0 = rf()
} else {
r0 = ret.Error(0)
}
return r0
}
......@@ -6,6 +6,7 @@ import (
"sort"
"github.com/sirupsen/logrus"
"gitlab.com/gitlab-org/gitlab-runner/helpers"
)
......@@ -20,57 +21,85 @@ type RunnerTextFormatter struct {
}
func (f *RunnerTextFormatter) Format(entry *logrus.Entry) ([]byte, error) {
var keys = make([]string, 0, len(entry.Data))
for k := range entry.Data {
keys = append(keys, k)
}
if !f.DisableSorting {
sort.Strings(keys)
}
b := bytes.Buffer{}
f.printColored(&b, entry, keys)
b := new(bytes.Buffer)
f.printColored(b, entry)
b.WriteByte('\n')
return b.Bytes(), nil
}
func (f *RunnerTextFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry, keys []string) {
var levelColor, levelText string
switch entry.Level {
case logrus.DebugLevel:
levelColor = helpers.ANSI_BOLD_WHITE
case logrus.WarnLevel:
levelColor = helpers.ANSI_YELLOW
levelText = "WARNING: "
case logrus.ErrorLevel:
levelColor = helpers.ANSI_BOLD_RED
levelText = "ERROR: "
case logrus.FatalLevel:
levelColor = helpers.ANSI_BOLD_RED
levelText = "FATAL: "
case logrus.PanicLevel:
levelColor = helpers.ANSI_BOLD_RED
levelText = "PANIC: "
default:
func (f *RunnerTextFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry) {
levelColor, resetColor, levelPrefix := f.getColorsAndPrefix(entry)
indentLength := 50 - len(levelPrefix)
fmt.Fprintf(b, "%s%s%-*s%s ", levelColor, levelPrefix, indentLength, entry.Message, resetColor)
for _, k := range f.prepareKeys(entry) {
v := entry.Data[k]
fmt.Fprintf(b, " %s%s%s=%v", levelColor, k, resetColor, v)
}
}
func (f *RunnerTextFormatter) getColorsAndPrefix(entry *logrus.Entry) (string, string, string) {
definitions := map[logrus.Level]struct {
color string
prefix string
}{
logrus.DebugLevel: {
color: helpers.ANSI_BOLD_WHITE,
},
logrus.WarnLevel: {
color: helpers.ANSI_YELLOW,
prefix: "WARNING: ",
},
logrus.ErrorLevel: {
color: helpers.ANSI_BOLD_RED,
prefix: "ERROR: ",
},
logrus.FatalLevel: {
color: helpers.ANSI_BOLD_RED,
prefix: "FATAL: ",
},
logrus.PanicLevel: {
color: helpers.ANSI_BOLD_RED,
prefix: "PANIC: ",
},
}
resetColor := helpers.ANSI_RESET
color := ""
prefix := ""
definition, ok := definitions[entry.Level]
if ok {
if definition.color != "" {
color = definition.color
}
if definition.prefix != "" {
prefix = definition.prefix
}
}
if f.DisableColors {
levelColor = ""
resetColor = ""
return "", "", prefix
}
indentLength := 50 - len(levelText)
return color, helpers.ANSI_RESET, prefix
}
fmt.Fprintf(b, "%s%s%-*s%s ", levelColor, levelText, indentLength, entry.Message, resetColor)
for _, k := range keys {
v := entry.Data[k]
fmt.Fprintf(b, " %s%s%s=%v", levelColor, k, resetColor, v)
func (f *RunnerTextFormatter) prepareKeys(entry *logrus.Entry) []string {
keys := make([]string, 0, len(entry.Data))
for k := range entry.Data {
keys = append(keys, k)
}
if !f.DisableSorting {
sort.Strings(keys)
}
return keys
}
func SetRunnerFormatter() {
logrus.SetFormatter(&RunnerTextFormatter{})
logrus.SetFormatter(new(RunnerTextFormatter))
}
package log
import (
"fmt"
"io/ioutil"
"testing"
"github.com/sirupsen/logrus"
"github.com/sirupsen/logrus/hooks/test"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"gitlab.com/gitlab-org/gitlab-runner/helpers"
)
func newNullLogger(formatter logrus.Formatter, level logrus.Level) *logrus.Logger {
logger := logrus.New()
logger.SetOutput(ioutil.Discard)
logger.SetFormatter(formatter)
logger.SetLevel(level)
return logger
}
type colorsAndPrefixesTestCase struct {
expectedPrefix string
expectedColorCode string
}
func TestRunnerTextFormatter_ColorsAndPrefixes(t *testing.T) {
logrus.RegisterExitHandler(func() {
panic("Fatal logged")
})
key := "key"
value := "value"
fields := logrus.Fields{
key: value,
}
tests := map[logrus.Level]colorsAndPrefixesTestCase{
logrus.PanicLevel: {
expectedPrefix: "PANIC: ",
expectedColorCode: helpers.ANSI_BOLD_RED,
},
// Fatal is skipped by purpose
//
// There is no way to disable or overwrite the `Exit(1)` called by logrus
// at the end of `Fatal` logger. We have our helpers.MakeFatalToPanic
// hook, but in this case it is unusable: hooks are fired before the formatting
// is done, and this is what we would like to test.
//
// We just need to assume, that if all other levels are working properly, then
// `Fatal` will also work. In the end, it's just another entry in the prefix/color
// choosing method.
logrus.ErrorLevel: {
expectedPrefix: "ERROR: ",
expectedColorCode: helpers.ANSI_BOLD_RED,
},
logrus.WarnLevel: {
expectedPrefix: "WARNING: ",
expectedColorCode: helpers.ANSI_YELLOW,
},
logrus.InfoLevel: {},
logrus.DebugLevel: {
expectedColorCode: helpers.ANSI_BOLD_WHITE,
},
}
for level, testCase := range tests {
for _, colored := range []bool{true, false} {
t.Run(fmt.Sprintf("%s-level colored-%v", level.String(), colored), func(t *testing.T) {
formatter := new(RunnerTextFormatter)
formatter.DisableColors = !colored
logger := newNullLogger(formatter, logrus.DebugLevel)
hook := test.NewLocal(logger)
defer testOutputColoringAndPrefix(t, key, value, testCase, colored, hook)
levels := map[logrus.Level]func(args ...interface{}){
logrus.PanicLevel: logger.WithFields(fields).Panic,
logrus.ErrorLevel: logger.WithFields(fields).Error,
logrus.WarnLevel: logger.WithFields(fields).Warning,
logrus.InfoLevel: logger.WithFields(fields).Info,
logrus.DebugLevel: logger.WithFields(fields).Debug,
}
levelLogger, ok := levels[level]
require.True(t, ok, "Unknown level %v used", level)
levelLogger("test message")
})
}
}
}
func testOutputColoringAndPrefix(t *testing.T, key string, value string, testCase colorsAndPrefixesTestCase, colored bool, hook *test.Hook) {
recover()
entry := hook.LastEntry()
require.NotNil(t, entry)
logrusOutput, err := entry.String()
require.NoError(t, err)
if testCase.expectedPrefix != "" {
assert.Contains(t, logrusOutput, testCase.expectedPrefix)
}
if colored {
if testCase.expectedColorCode != "" {
assert.Contains(t, logrusOutput, testCase.expectedColorCode, "Should contain color code")
}
assert.Contains(t, logrusOutput, helpers.ANSI_RESET, "Should contain reset color code")
assert.Contains(t, logrusOutput, fmt.Sprintf("%s%s%s=%s", testCase.expectedColorCode, key, helpers.ANSI_RESET, value), "Should color field key")
} else {
if testCase.expectedColorCode != "" {
assert.NotContains(t, logrusOutput, testCase.expectedColorCode, "Shouldn't contain color code")
}
assert.NotContains(t, logrusOutput, helpers.ANSI_RESET, "Shouldn't contain reset color code")
assert.Contains(t, logrusOutput, fmt.Sprintf("%s=%s", key, value), "Shouldn't color field key")
}
}
func TestRunnerTextFormatter_KeysSorting(t *testing.T) {
fields := logrus.Fields{
"aza": "v",
"zzz": "v",
"zaz": "v",
"aaa": "v",
}
formatter := new(RunnerTextFormatter)
formatter.DisableColors = true
formatter.DisableSorting = false
logger := newNullLogger(formatter, logrus.InfoLevel)
hook := test.NewLocal(logger)
for i := 0; i <= 2; i++ {
logger.WithFields(fields).Info("test message")
entry := hook.LastEntry()
require.NotNil(t, entry)
logrusOutput, err := entry.String()
require.NoError(t, err)
assert.Contains(t, logrusOutput, " aaa=v aza=v zaz=v zzz=v")
}
}
......@@ -5,12 +5,20 @@ import (
"github.com/sirupsen/logrus"
)
type ServiceLogHook struct {
type systemLogger interface {
service.Logger
}
type systemService interface {
service.Service
}
type SystemServiceLogHook struct {
systemLogger
Level logrus.Level
}
func (s *ServiceLogHook) Levels() []logrus.Level {
func (s *SystemServiceLogHook) Levels() []logrus.Level {
return []logrus.Level{
logrus.PanicLevel,
logrus.FatalLevel,
......@@ -20,7 +28,7 @@ func (s *ServiceLogHook) Levels() []logrus.Level {
}
}
func (s *ServiceLogHook) Fire(entry *logrus.Entry) error {
func (s *SystemServiceLogHook) Fire(entry *logrus.Entry) error {
if entry.Level > s.Level {
return nil
}
......@@ -42,12 +50,16 @@ func (s *ServiceLogHook) Fire(entry *logrus.Entry) error {
return nil
}
func SetSystemLogger(svc service.Service) {
func SetSystemLogger(logrusLogger *logrus.Logger, svc systemService) {
logger, err := svc.SystemLogger(nil)
if err == nil {
logrus.AddHook(&ServiceLogHook{logger, logrus.GetLevel()})
hook := new(SystemServiceLogHook)
hook.systemLogger = logger
hook.Level = logrus.GetLevel()
logrusLogger.AddHook(hook)
} else {
logrus.WithError(err).Error("Error while setting up the system logger")
logrusLogger.WithError(err).Error("Error while setting up the system logger")
}
}
package log
import (
"os"
"fmt"
"io/ioutil"
"testing"
"github.com/sirupsen/logrus"
"gitlab.com/gitlab-org/gitlab-runner/helpers/service/mocks"
"github.com/sirupsen/logrus/hooks/test"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/mock"
"github.com/stretchr/testify/require"
)
func TestServiceLogHook(t *testing.T) {
formatter := new(logrus.TextFormatter)
formatter.DisableColors = true
formatter.DisableTimestamp = true
logger := &logrus.Logger{
Formatter: formatter,
Hooks: make(logrus.LevelHooks),
Level: logrus.InfoLevel,
Out: os.Stderr,
key := "key"
value := "value"
testMessage := "test message"
tests := map[logrus.Level]string{
logrus.InfoLevel: "Info",
logrus.WarnLevel: "Warning",
logrus.ErrorLevel: "Error",
// Fatal is skipped by purpose
//
// There is no way to disable or overwrite the `Exit(1)` called by logrus
// at the end of `Fatal` logger. We have our helpers.MakeFatalToPanic
// hook, but it doesn't work reliable here.
//
// We just need to assume, that if all other levels are working properly, then
// `Fatal` will also work. In the end, it's just another entry in the systemLogger
// method selector.
logrus.PanicLevel: "Error",
}
for level, sysLoggerMethod := range tests {
t.Run(fmt.Sprintf("level-%s", level), func(t *testing.T) {
defer func() {
recover()
}()
sysLogger := new(mockSystemLogger)
defer sysLogger.AssertExpectations(t)
sysService := new(mockSystemService)
defer sysService.AssertExpectations(t)
sysService.On("SystemLogger", mock.Anything).Return(sysLogger, nil).Once()
logger := logrus.New()
logger.SetLevel(logrus.InfoLevel)
logger.SetOutput(ioutil.Discard)
SetSystemLogger(logger, sysService)
sysLogger.On(sysLoggerMethod, mock.Anything).Return(nil).Once().Run(func(args mock.Arguments) {
msg := args.Get(0)
assert.Contains(t, msg, fmt.Sprintf("msg=%q %s=%s", testMessage, key, value))
})
levels := map[logrus.Level]func(args ...interface{}){
logrus.PanicLevel: logger.WithField(key, value).Panic,
logrus.ErrorLevel: logger.WithField(key, value).Error,
logrus.WarnLevel: logger.WithField(key, value).Warning,
logrus.InfoLevel: logger.WithField(key, value).Info,
logrus.DebugLevel: logger.WithField(key, value).Debug,
}
levelLogger, ok := levels[level]
require.True(t, ok, "Unknown level %v used", level)
levelLogger(testMessage)
})
}
}
func TestServiceLogHookWithSpecifiedLevel(t *testing.T) {
entry := logrus.NewEntry(logrus.New())
entry.Message = "test message"
sysLogger := new(mockSystemLogger)
defer sysLogger.AssertExpectations(t)
assertSysLoggerMethod := func(args mock.Arguments) {
msg := args.Get(0)
assert.Contains(t, msg, `msg="test message"`)
}
sysLogger.On("Error", mock.Anything).Return(nil).Once().Run(assertSysLoggerMethod)
sysLogger.On("Warning", mock.Anything).Return(nil).Once().Run(assertSysLoggerMethod)
hook := new(SystemServiceLogHook)
hook.systemLogger = sysLogger
hook.Level = logrus.WarnLevel
for _, level := range []logrus.Level{
logrus.ErrorLevel,
logrus.WarnLevel,
logrus.InfoLevel,
} {
entry.Level = level
err := hook.Fire(entry)
assert.NoError(t, err)
}
}
func TestSetSystemLogger_ErrorOnInitialization(t *testing.T) {
logger, hook := test.NewNullLogger()
mockServiceLogger := new(mocks.Logger)
mockServiceLogger.On("Info", "level=info msg=test\n").Return(nil)
sysService := new(mockSystemService)
defer sysService.AssertExpectations(t)
sysService.On("SystemLogger", mock.Anything).Return(nil, fmt.Errorf("test error")).Once()
logHook := &ServiceLogHook{mockServiceLogger, logrus.InfoLevel}