general improvements (#2)

* Replaced strutil.Md5 with crypto/md5 and encoding/hex to reduce dependency and potential allocations.

* Move to improved logging library.

* fixup! Move to improved logging library.
This commit is contained in:
2024-06-28 09:22:52 +01:00
committed by GitHub
parent 42170f9b8e
commit 36ef16ad3d
13 changed files with 755 additions and 185 deletions
+204
View File
@@ -0,0 +1,204 @@
package libpack_logger
import (
"bytes"
"flag"
"fmt"
"io"
"os"
"path/filepath"
"runtime"
"strings"
"sync"
"time"
"github.com/goccy/go-json"
)
const (
_ = iota
LEVEL_DEBUG
LEVEL_INFO
LEVEL_WARN
LEVEL_ERROR
LEVEL_FATAL
)
var LevelNames = [...]string{
"none",
"debug",
"info",
"warn",
"error",
"fatal",
}
const (
defaultFormat = time.RFC3339
defaultMinLevel = LEVEL_INFO
defaultShowCaller = false
)
var defaultOutput = os.Stdout
type Logger struct {
output io.Writer
format string
minLogLevel int
showCaller bool
}
type LogMessage struct {
output io.Writer
Pairs map[string]any
Message string
}
func (m *LogMessage) String() string {
return m.Message
}
var fieldNames = map[string]string{
"timestamp": "timestamp",
"level": "level",
"message": "message",
}
func New() *Logger {
return &Logger{
format: defaultFormat,
minLogLevel: defaultMinLevel,
output: defaultOutput,
showCaller: defaultShowCaller,
}
}
func (l *Logger) SetOutput(output io.Writer) *Logger {
l.output = output
return l
}
var bufferPool = sync.Pool{
New: func() any {
return new(bytes.Buffer)
},
}
var defaultPairs = make(map[string]any)
func GetLogLevel(level string) int {
for i, name := range LevelNames {
if name == strings.ToLower(level) {
return i
}
}
return defaultMinLevel
}
func (l *Logger) log(level int, m *LogMessage) {
if m.Pairs == nil {
m.Pairs = defaultPairs
}
m.Pairs[fieldNames["timestamp"]] = time.Now().Format(l.format)
m.Pairs[fieldNames["level"]] = LevelNames[level]
m.Pairs[fieldNames["message"]] = m.Message
if l.showCaller {
m.Pairs["caller"] = getCaller()
}
buffer := bufferPool.Get().(*bytes.Buffer)
defer bufferPool.Put(buffer)
buffer.Reset()
var encoder = json.NewEncoder(buffer)
err := encoder.Encode(m.Pairs)
if err != nil {
fmt.Println("Error marshalling log message:", err)
return
}
// if not running in test - use stderr and stdout, otherwise - use logger's output setting
if flag.Lookup("test.v") != nil {
m.output = os.Stdout
if level >= LEVEL_ERROR {
m.output = os.Stderr
}
}
// Use logger's output setting instead of os.Stdout or os.Stderr
l.output.Write(buffer.Bytes())
}
func (l *Logger) Debug(m *LogMessage) {
if l.shouldLog(LEVEL_DEBUG) {
l.log(LEVEL_DEBUG, m)
}
}
func (l *Logger) Info(m *LogMessage) {
if l.shouldLog(LEVEL_INFO) {
l.log(LEVEL_INFO, m)
}
}
func (l *Logger) Warn(m *LogMessage) {
if l.shouldLog(LEVEL_WARN) {
l.log(LEVEL_WARN, m)
}
}
func (l *Logger) Warning(m *LogMessage) {
l.Warn(m)
}
func (l *Logger) Error(m *LogMessage) {
if l.shouldLog(LEVEL_ERROR) {
l.log(LEVEL_ERROR, m)
}
}
func (l *Logger) Fatal(m *LogMessage) {
if l.shouldLog(LEVEL_FATAL) {
l.log(LEVEL_FATAL, m)
}
}
func (l *Logger) Critical(m *LogMessage) {
l.Fatal(m)
os.Exit(1)
}
func (l *Logger) shouldLog(level int) bool {
return level >= l.minLogLevel
}
func (l *Logger) SetFormat(format string) *Logger {
l.format = format
return l
}
func (l *Logger) SetMinLogLevel(level int) *Logger {
l.minLogLevel = level
return l
}
func (l *Logger) SetFieldName(field, name string) *Logger {
fieldNames[field] = name
return l
}
func (l *Logger) SetShowCaller(show bool) *Logger {
l.showCaller = show
return l
}
func getCaller() string {
_, file, line, ok := runtime.Caller(3)
if !ok {
return "unknown:0"
}
file = filepath.Base(file)
return fmt.Sprintf("%s:%d", file, line)
}
+140
View File
@@ -0,0 +1,140 @@
package libpack_logger
import (
"bytes"
"testing"
"time"
)
func Benchmark_NewLogger(b *testing.B) {
type triggers struct {
ModFormat struct {
Format string
}
ModLevel struct {
Level int
}
}
tests := []struct {
name string
triggers triggers
}{
{
name: "BenchmarkNew",
},
{
name: "BenchmarkNewChangeTimeFormat",
triggers: triggers{
ModFormat: struct{ Format string }{
Format: time.RFC3339Nano,
},
},
},
{
name: "BenchmarkNewChangeLogLevel",
triggers: triggers{
ModLevel: struct{ Level int }{
Level: LEVEL_DEBUG,
},
},
},
{
name: "BenchmarkNewChangeTimeFormatAndLogLevel",
triggers: triggers{
ModFormat: struct{ Format string }{
Format: time.RFC3339Nano,
},
ModLevel: struct{ Level int }{
Level: LEVEL_DEBUG,
},
},
},
}
for _, tt := range tests {
b.Run(tt.name, func(b *testing.B) {
for i := 0; i < b.N; i++ {
got := New()
if tt.triggers.ModFormat.Format != "" {
got = got.SetFormat(tt.triggers.ModFormat.Format)
}
if tt.triggers.ModLevel.Level != 0 {
got = got.SetMinLogLevel(tt.triggers.ModLevel.Level)
}
}
})
}
}
func Benchmark_Log_Debug(b *testing.B) {
output := &bytes.Buffer{}
logger := New().SetMinLogLevel(LEVEL_DEBUG).SetOutput(output)
msg := &LogMessage{
Message: "debug message",
Pairs: make(map[string]any),
}
b.ResetTimer()
for i := 0; i < b.N; i++ {
logger.Debug(msg)
}
}
func Benchmark_Log_Info(b *testing.B) {
output := &bytes.Buffer{}
logger := New().SetMinLogLevel(LEVEL_INFO).SetOutput(output)
msg := &LogMessage{
Message: "info message",
Pairs: make(map[string]any),
}
b.ResetTimer()
for i := 0; i < b.N; i++ {
logger.Info(msg)
}
}
func Benchmark_Log_Warn(b *testing.B) {
output := &bytes.Buffer{}
logger := New().SetMinLogLevel(LEVEL_WARN).SetOutput(output)
msg := &LogMessage{
Message: "warn message",
Pairs: make(map[string]any),
}
b.ResetTimer()
for i := 0; i < b.N; i++ {
logger.Warn(msg)
}
}
func Benchmark_Log_Error(b *testing.B) {
output := &bytes.Buffer{}
logger := New().SetMinLogLevel(LEVEL_ERROR).SetOutput(output)
msg := &LogMessage{
Message: "error message",
Pairs: map[string]any{"key": "value"},
}
b.ResetTimer()
for i := 0; i < b.N; i++ {
logger.Error(msg)
}
}
func Benchmark_Log_Fatal(b *testing.B) {
output := &bytes.Buffer{}
logger := New().SetMinLogLevel(LEVEL_FATAL).SetOutput(output)
msg := &LogMessage{
Message: "fatal message",
Pairs: make(map[string]any),
}
b.ResetTimer()
for i := 0; i < b.N; i++ {
logger.Fatal(msg)
}
}
+31
View File
@@ -0,0 +1,31 @@
package libpack_logger
import (
"testing"
assertions "github.com/stretchr/testify/assert"
"github.com/stretchr/testify/suite"
)
type LoggerTestSuite struct {
suite.Suite
}
var (
assert *assertions.Assertions
)
func (suite *LoggerTestSuite) BeforeTest(suiteName, testName string) {
}
func (suite *LoggerTestSuite) SetupTest() {
assert = assertions.New(suite.T())
}
// TearDownTest is run after each test to clean up
func (suite *LoggerTestSuite) TearDownTest() {
}
func TestSuite(t *testing.T) {
suite.Run(t, new(LoggerTestSuite))
}
+182
View File
@@ -0,0 +1,182 @@
package libpack_logger
import (
"bytes"
"fmt"
"os"
"reflect"
"testing"
"time"
"github.com/goccy/go-json"
)
func captureStderr(f func()) string {
originalStderr := os.Stderr
r, w, _ := os.Pipe()
os.Stderr = w
f()
w.Close()
var buf bytes.Buffer
buf.ReadFrom(r)
os.Stderr = originalStderr
return buf.String()
}
func captureStdOut(f func()) string {
originalStdout := os.Stdout
r, w, _ := os.Pipe()
os.Stdout = w
f()
w.Close()
var buf bytes.Buffer
buf.ReadFrom(r)
os.Stdout = originalStdout
return buf.String()
}
func (suite *LoggerTestSuite) Test_LogMessageString() {
msg := &LogMessage{
Message: "test message",
}
assert.Equal("test message", msg.String())
}
func callLoggerMethod(logger *Logger, methodName string, message *LogMessage) {
// Get the method by name using reflection
method := reflect.ValueOf(logger).MethodByName(methodName)
if method.IsValid() {
// Call the method with the message as an argument
method.Call([]reflect.Value{reflect.ValueOf(message)})
} else {
fmt.Printf("Method %s does not exist on Logger\n", methodName)
}
}
func (suite *LoggerTestSuite) Test_LogsLevelsPrint() {
output := &bytes.Buffer{}
logger := New().SetOutput(output)
tests := []struct {
pairs map[string]any
name string
method string
message string
loggerMinLevel int
messageLogLevel int
wantOutput bool
}{
{
name: "Log: Debug, Level: Debug - no pairs",
method: "Debug",
loggerMinLevel: LEVEL_DEBUG,
messageLogLevel: LEVEL_DEBUG,
message: "debug message",
wantOutput: true,
},
{
name: "Log: Info, Level: Info - one pair",
method: "Info",
loggerMinLevel: LEVEL_INFO,
messageLogLevel: LEVEL_INFO,
message: "info message",
pairs: map[string]any{
"key": "value",
},
wantOutput: true,
},
{
name: "Log: Info, Level: Warn - with pairs",
method: "Info",
loggerMinLevel: LEVEL_WARN,
messageLogLevel: LEVEL_INFO,
message: "warn message",
pairs: map[string]any{
"key1": "value1",
"key2": "value2",
},
wantOutput: false,
},
{
name: "Log: Warn, Level: Info - with 500 pairs",
method: "Warn",
loggerMinLevel: LEVEL_INFO,
messageLogLevel: LEVEL_WARN,
message: "warn message with 500 pairs",
pairs: func() map[string]any {
pairs := make(map[string]any)
for i := 0; i < 500; i++ {
pairs[fmt.Sprintf("key%d", i)] = fmt.Sprintf("value%d", i)
}
return pairs
}(),
wantOutput: true,
},
}
for _, tt := range tests {
suite.T().Run(tt.name, func(t *testing.T) {
msg := &LogMessage{
Message: tt.message,
Pairs: tt.pairs,
}
output.Reset()
// Set logger's minimum log level
logger.SetMinLogLevel(tt.loggerMinLevel)
fmt.Println("Logger min log level:", LevelNames[logger.minLogLevel])
// Call the logging method
callLoggerMethod(logger, tt.method, msg)
logOutput := output.String()
fmt.Println("Output:", logOutput)
if tt.wantOutput {
var loggedMessage map[string]any
err := json.Unmarshal([]byte(logOutput), &loggedMessage)
if err != nil {
t.Fatalf("Error unmarshalling log message: %v\nLog output: %s", err, logOutput)
}
if !containsLogMessage(logOutput, tt.message) {
t.Errorf("Expected log message %q, but got %q", tt.message, logOutput)
}
assert.Equal(LevelNames[tt.messageLogLevel], loggedMessage["level"])
if tt.pairs != nil {
for k, v := range tt.pairs {
assert.Equal(v, loggedMessage[k])
}
}
} else {
assert.Equal("", logOutput)
}
})
}
}
func containsLogMessage(logOutput, expectedMessage string) bool {
return bytes.Contains([]byte(logOutput), []byte(expectedMessage))
}
func (suite *LoggerTestSuite) Test_SetFormat() {
logger := New().SetFormat(time.RFC3339Nano)
assert.Equal(time.RFC3339Nano, logger.format)
}
func (suite *LoggerTestSuite) Test_SetMinLogLevel() {
logger := New().SetMinLogLevel(LEVEL_DEBUG)
assert.Equal(LEVEL_DEBUG, logger.minLogLevel)
}
func (suite *LoggerTestSuite) Test_ShouldLog() {
logger := New().SetMinLogLevel(LEVEL_WARN)
assert.True(logger.shouldLog(LEVEL_WARN))
assert.True(logger.shouldLog(LEVEL_ERROR))
assert.False(logger.shouldLog(LEVEL_INFO))
assert.False(logger.shouldLog(LEVEL_DEBUG))
}
-120
View File
@@ -1,120 +0,0 @@
package libpack_logging
import (
"io"
"os"
"sync"
"time"
"github.com/gookit/goutil/envutil"
"github.com/rs/zerolog"
)
type LogConfig struct {
logger zerolog.Logger
}
var (
baseLogger zerolog.Logger
eventPool = sync.Pool{
New: func() interface{} {
return new(zerolog.Event)
},
}
fieldMapPool = sync.Pool{
New: func() interface{} {
return make(map[string]interface{})
},
}
)
func init() {
zerolog.TimeFieldFormat = time.RFC3339
zerolog.MessageFieldName = "short_message"
zerolog.TimestampFieldName = "timestamp"
zerolog.LevelFieldName = "level"
zerolog.LevelFatalValue = "critical"
baseLogger = zerolog.New(os.Stdout).With().Timestamp().Logger()
switch logLevel := envutil.Getenv("LOG_LEVEL", "info"); logLevel {
case "debug":
baseLogger = baseLogger.Level(zerolog.DebugLevel)
case "warn":
baseLogger = baseLogger.Level(zerolog.WarnLevel)
case "error":
baseLogger = baseLogger.Level(zerolog.ErrorLevel)
default:
baseLogger = baseLogger.Level(zerolog.InfoLevel)
}
}
func NewLogger() *LogConfig {
return &LogConfig{logger: baseLogger}
}
func (lw *LogConfig) log(w io.Writer, level zerolog.Level, message string, fields map[string]interface{}) {
logger := lw.logger.Output(w)
event := logger.WithLevel(level).CallerSkipFrame(3)
for k, val := range fields {
switch v := val.(type) {
case string:
event = event.Str(k, v)
case int:
event = event.Int(k, v)
case float64:
event = event.Float64(k, v)
default:
event = event.Interface(k, val)
}
}
event.Msg(message)
}
func (lw *LogConfig) logWithLevel(level zerolog.Level, message string, fields map[string]interface{}) {
if lw.logger.GetLevel() <= level {
w := os.Stdout
if level >= zerolog.ErrorLevel {
w = os.Stderr
}
lw.log(w, level, message, fields)
}
}
func (lw *LogConfig) Debug(message string, fields map[string]interface{}) {
lw.logWithLevel(zerolog.DebugLevel, message, fields)
}
func (lw *LogConfig) Info(message string, fields map[string]interface{}) {
lw.logWithLevel(zerolog.InfoLevel, message, fields)
}
func (lw *LogConfig) Warning(message string, fields map[string]interface{}) {
lw.logWithLevel(zerolog.WarnLevel, message, fields)
}
func (lw *LogConfig) Error(message string, fields map[string]interface{}) {
lw.logWithLevel(zerolog.ErrorLevel, message, fields)
}
func (lw *LogConfig) Critical(message string, fields map[string]interface{}) {
lw.logWithLevel(zerolog.FatalLevel, message, fields)
os.Exit(1)
}
// Helper function to get a new fields map from the pool
func getFieldsMap() map[string]interface{} {
return fieldMapPool.Get().(map[string]interface{})
}
// Helper function to put a used fields map back into the pool
func putFieldsMap(fields map[string]interface{}) {
for k := range fields {
delete(fields, k)
}
fieldMapPool.Put(fields)
}
-32
View File
@@ -1,32 +0,0 @@
package libpack_logging
import (
"os"
"testing"
)
func BenchmarkNewLogger(b *testing.B) {
for i := 0; i < b.N; i++ {
NewLogger()
}
}
func BenchmarkInfoLog(b *testing.B) {
oldEnv := os.Getenv("LOG_LEVEL")
os.Setenv("LOG_LEVEL", "info")
oldStdout := os.Stdout
oldStderr := os.Stderr
os.Stdout, _ = os.Open(os.DevNull)
os.Stderr, _ = os.Open(os.DevNull)
defer func() {
os.Stdout = oldStdout
os.Stderr = oldStderr
os.Setenv("LOG_LEVEL", oldEnv)
}()
testsLogger := NewLogger()
b.ResetTimer()
for i := 0; i < b.N; i++ {
testsLogger.Info("test", map[string]interface{}{"test": "test"})
}
}