From f999b8a5ed7a81099a71edea0806e50f59e6d9aa Mon Sep 17 00:00:00 2001 From: Lukasz Raczylo Date: Sat, 15 Jun 2024 23:05:39 +0100 Subject: [PATCH 1/3] Replaced strutil.Md5 with crypto/md5 and encoding/hex to reduce dependency and potential allocations. --- helpers.go | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/helpers.go b/helpers.go index 47f4707..e760e81 100644 --- a/helpers.go +++ b/helpers.go @@ -1,10 +1,11 @@ package gql import ( + "crypto/md5" + "encoding/hex" "fmt" "github.com/goccy/go-json" - "github.com/gookit/goutil/strutil" ) func searchForKeysInMapStringInterface(msi map[string]interface{}, key string) (value any) { @@ -15,7 +16,8 @@ func searchForKeysInMapStringInterface(msi map[string]interface{}, key string) ( } func calculateHash(query *Query) string { - return strutil.Md5(query.JsonQuery) + hash := md5.Sum([]byte(query.JsonQuery)) + return hex.EncodeToString(hash[:]) } func (b *BaseClient) cacheLookup(hash string) []byte { From 0a192d179d9d774a6c5e912de6135ad6fc8ac08d Mon Sep 17 00:00:00 2001 From: Lukasz Raczylo Date: Fri, 28 Jun 2024 09:06:12 +0100 Subject: [PATCH 2/3] Move to improved logging library. --- .github/workflows/autoupdate.yaml | 72 ++++++++++++++++++ execute_query.go | 71 ++++++++++++++---- helpers.go | 11 ++- http.go | 15 +++- logging/logging.go | 120 ------------------------------ logging/logging_bench_test.go | 32 -------- main.go | 8 +- query.go | 46 +++++++++--- structs.go | 2 +- 9 files changed, 194 insertions(+), 183 deletions(-) create mode 100644 .github/workflows/autoupdate.yaml delete mode 100644 logging/logging.go delete mode 100644 logging/logging_bench_test.go diff --git a/.github/workflows/autoupdate.yaml b/.github/workflows/autoupdate.yaml new file mode 100644 index 0000000..9d66468 --- /dev/null +++ b/.github/workflows/autoupdate.yaml @@ -0,0 +1,72 @@ +name: Autoupdate go.mod and go.sum + +on: + workflow_dispatch: + schedule: + - cron: "30 2 * * *" + +env: + GO_VERSION: ">=1.21" + +jobs: + # This job is responsible for preparation of the build + # environment variables. + prepare: + name: Preparing build context + runs-on: ubuntu-latest + + steps: + - name: Checkout repo + uses: actions/checkout@v4 + + - name: Install Go + uses: actions/setup-go@v5 + id: cache + with: + go-version: ${{env.GO_VERSION}} + cache-dependency-path: "**/*.sum" + + - name: Go get dependencies + if: steps.cache.outputs.cache-hit != 'true' + run: | + go get ./... + + # This job is responsible for running tests and linting the codebase + test: + name: "Unit testing" + runs-on: ubuntu-latest + container: golang:1 + needs: [prepare] + + steps: + - name: Checkout repository + uses: actions/checkout@v4 + with: + fetch-depth: 0 # Ensure full history is checked out + token: ${{ secrets.GHCR_TOKEN }} + + - name: Install Go + uses: actions/setup-go@v5 + with: + go-version: ${{env.GO_VERSION}} + cache-dependency-path: "**/*.sum" + + - name: Install dependencies + run: | + apt-get update + apt-get install ca-certificates make -y + update-ca-certificates + go mod tidy + go get -u -v ./... + go mod tidy -v + + - name: Run unit tests + run: | + CI_RUN=${CI} make test + git config --global --add safe.directory /__w/go-simple-graphql + - name: Commit changes + uses: stefanzweifel/git-auto-commit-action@v5 + with: + commit_message: "Update go.mod and go.sum" + commit_options: "--no-verify --signoff" + file_pattern: "go.mod go.sum" diff --git a/execute_query.go b/execute_query.go index cb96295..177371e 100644 --- a/execute_query.go +++ b/execute_query.go @@ -12,6 +12,7 @@ import ( "github.com/avast/retry-go/v4" "github.com/goccy/go-json" + libpack_logger "github.com/lukaszraczylo/go-simple-graphql/logging" ) var bufferPool = sync.Pool{ @@ -28,13 +29,19 @@ func (qe *QueryExecutor) executeQuery() ([]byte, error) { _, err := buf.Write(qe.Query) if err != nil { - qe.Logger.Error("Can't write to buffer", map[string]interface{}{"error": err}) + qe.Logger.Error(&libpack_logger.LogMessage{ + Message: "Can't write to buffer", + Pairs: map[string]interface{}{"error": err.Error()}, + }) return nil, err } httpRequest, err := http.NewRequest(http.MethodPost, qe.endpoint, buf) if err != nil { - qe.Logger.Error("Can't create HTTP request", map[string]interface{}{"error": err}) + qe.Logger.Error(&libpack_logger.LogMessage{ + Message: "Can't create HTTP request", + Pairs: map[string]interface{}{"error": err.Error()}, + }) return nil, err } @@ -44,10 +51,16 @@ func (qe *QueryExecutor) executeQuery() ([]byte, error) { retriesMax := 1 if qe.Retries { - qe.Logger.Debug("Retries enabled", map[string]interface{}{"retries": qe.retries_number}) + qe.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Retries enabled", + Pairs: map[string]interface{}{"retries": qe.retries_number}, + }) retriesMax = qe.retries_number } else { - qe.Logger.Debug("Retries disabled", map[string]interface{}{"retries": 1}) + qe.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Retries disabled", + Pairs: map[string]interface{}{"retries": 1}, + }) } var queryResult queryResults @@ -55,13 +68,19 @@ func (qe *QueryExecutor) executeQuery() ([]byte, error) { func() error { httpResponse, err := qe.client.Do(httpRequest) if err != nil { - qe.Logger.Debug("Error executing HTTP request", map[string]interface{}{"error": err.Error()}) + qe.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Error executing HTTP request", + Pairs: map[string]interface{}{"error": err.Error()}, + }) return err } defer func() { _, err := io.Copy(io.Discard, httpResponse.Body) if err != nil { - qe.Logger.Debug("Error discarding HTTP response body", map[string]interface{}{"error": err.Error()}) + qe.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Error discarding HTTP response body", + Pairs: map[string]interface{}{"error": err.Error()}, + }) } httpResponse.Body.Close() }() @@ -75,7 +94,10 @@ func (qe *QueryExecutor) executeQuery() ([]byte, error) { if encoding == "gzip" { reader, err = gzip.NewReader(httpResponse.Body) if err != nil { - qe.Logger.Debug("Error creating gzip reader", map[string]interface{}{"error": err.Error()}) + qe.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Error creating gzip reader", + Pairs: map[string]interface{}{"error": err.Error()}, + }) return fmt.Errorf("error creating gzip reader: %w", err) } defer reader.Close() @@ -85,20 +107,29 @@ func (qe *QueryExecutor) executeQuery() ([]byte, error) { body, err := io.ReadAll(reader) if err != nil { - qe.Logger.Debug("Error reading HTTP response", map[string]interface{}{"error": err.Error()}) + qe.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Error reading HTTP response", + Pairs: map[string]interface{}{"error": err.Error()}, + }) return fmt.Errorf("error reading HTTP response: %w", err) } err = json.Unmarshal(body, &queryResult) if err != nil { - qe.Logger.Debug("Error unmarshalling HTTP response", map[string]interface{}{"error": err.Error()}) + qe.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Error unmarshalling HTTP response", + Pairs: map[string]interface{}{"error": err.Error()}, + }) return fmt.Errorf("error unmarshalling HTTP response: %w", err) } return nil }, retry.OnRetry(func(n uint, err error) { - qe.Logger.Warning("Retrying query", map[string]interface{}{"error": err.Error(), "attempt": n + 1}) + qe.Logger.Warning(&libpack_logger.LogMessage{ + Message: "Retrying query", + Pairs: map[string]interface{}{"error": err.Error(), "attempt": n + 1}, + }) }), retry.Attempts(uint(retriesMax)), retry.DelayType(retry.BackOffDelay), @@ -106,23 +137,35 @@ func (qe *QueryExecutor) executeQuery() ([]byte, error) { retry.LastErrorOnly(true), ) if err != nil { - qe.Logger.Debug("Error executing HTTP request", map[string]interface{}{"error": err.Error()}) + qe.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Error executing HTTP request", + Pairs: map[string]interface{}{"error": err.Error()}, + }) return nil, err } if len(queryResult.Errors) > 0 { - qe.Logger.Debug("Error executing query", map[string]interface{}{"error": queryResult.Errors}) + qe.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Error executing query", + Pairs: map[string]interface{}{"error": queryResult.Errors}, + }) return nil, fmt.Errorf("error executing query: %s", queryResult.Errors) } if queryResult.Data == nil { - qe.Logger.Debug("Error executing query", map[string]interface{}{"error": "no data"}) + qe.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Error executing query", + Pairs: map[string]interface{}{"error": "no data"}, + }) return nil, errors.New("error executing query: no data") } jsonData, err := json.Marshal(queryResult.Data) if err != nil { - qe.Logger.Debug("Error marshalling query result", map[string]interface{}{"error": err.Error(), "data": queryResult.Data}) + qe.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Error marshalling query result", + Pairs: map[string]interface{}{"error": err.Error(), "data": queryResult.Data}, + }) return nil, fmt.Errorf("error marshalling query result: %w. Data: %s", err, queryResult.Data) } diff --git a/helpers.go b/helpers.go index e760e81..e5d54a8 100644 --- a/helpers.go +++ b/helpers.go @@ -6,6 +6,7 @@ import ( "fmt" "github.com/goccy/go-json" + libpack_logger "github.com/lukaszraczylo/go-simple-graphql/logging" ) func searchForKeysInMapStringInterface(msi map[string]interface{}, key string) (value any) { @@ -31,7 +32,10 @@ func (b *BaseClient) decodeResponse(response []byte) (any, error) { var result map[string]interface{} err := json.Unmarshal(response, &result) if err != nil { - b.Logger.Error("Can't decode response into mapstring", map[string]interface{}{"error": err.Error()}) + b.Logger.Error(&libpack_logger.LogMessage{ + Message: "Can't decode response into mapstring", + Pairs: map[string]interface{}{"error": err.Error()}, + }) return nil, err } return result, nil @@ -40,7 +44,10 @@ func (b *BaseClient) decodeResponse(response []byte) (any, error) { case "byte": return response, nil default: - b.Logger.Error("Can't decode response;", map[string]interface{}{"error": "unknown response type"}) + b.Logger.Error(&libpack_logger.LogMessage{ + Message: "Can't decode response", + Pairs: map[string]interface{}{"error": "unknown response type"}, + }) return nil, fmt.Errorf("Can't decode response - unknown response type specified") } } diff --git a/http.go b/http.go index 5977140..ea71830 100644 --- a/http.go +++ b/http.go @@ -6,6 +6,7 @@ import ( "strings" "time" + libpack_logger "github.com/lukaszraczylo/go-simple-graphql/logging" "golang.org/x/net/http2" ) @@ -28,7 +29,10 @@ func (b *BaseClient) createHttpClient() (http_client *http.Client) { return http.ErrUseLastResponse }, } - b.Logger.Debug("Using HTTP/1.1 over http", nil) + b.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Using HTTP/1.1 over http", + Pairs: nil, + }) } else if strings.HasPrefix(b.endpoint, "https://") { tlsClientConfig := &tls.Config{} if strings.HasPrefix(b.endpoint, "https://") { @@ -46,9 +50,14 @@ func (b *BaseClient) createHttpClient() (http_client *http.Client) { return http.ErrUseLastResponse }, } - b.Logger.Debug("Using HTTP/2 over https", nil) + b.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Using HTTP/2 over https", + Pairs: nil, + }) } else { - b.Logger.Critical("Invalid endpoint - neither http or https", nil) + b.Logger.Critical(&libpack_logger.LogMessage{ + Message: "Invalid endpoint - neither http or https", + }) } return http_client } diff --git a/logging/logging.go b/logging/logging.go deleted file mode 100644 index 45ec3be..0000000 --- a/logging/logging.go +++ /dev/null @@ -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) -} diff --git a/logging/logging_bench_test.go b/logging/logging_bench_test.go deleted file mode 100644 index 68da011..0000000 --- a/logging/logging_bench_test.go +++ /dev/null @@ -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"}) - } -} diff --git a/main.go b/main.go index 6496822..3015951 100644 --- a/main.go +++ b/main.go @@ -12,7 +12,7 @@ func NewConnection() (b *BaseClient) { b = &BaseClient{ endpoint: envutil.Getenv("GRAPHQL_ENDPOINT", "https://api.github.com/graphql"), responseType: envutil.Getenv("GRAPHQL_OUTPUT", "string"), - Logger: logging.NewLogger(), + Logger: logging.New(), cache: cache.New(time.Duration(envutil.GetInt("GRAPHQL_CACHE_TTL", 5)) * time.Second), cache_global: envutil.GetBool("GRAPHQL_CACHE_ENABLED", false), retries_enable: envutil.GetBool("GRAPHQL_RETRIES_ENABLE", false), @@ -20,7 +20,11 @@ func NewConnection() (b *BaseClient) { retries_number: envutil.GetInt("GRAPHQL_RETRIES_NUMBER", 3), } b.client = b.createHttpClient() - b.Logger.Debug("Created new GraphQL client connection", map[string]interface{}{"values": b}) + b.Logger.Debug(&logging.LogMessage{ + Message: "Created new GraphQL client connection", + Pairs: map[string]interface{}{ + "values": b, + }}) return b } diff --git a/query.go b/query.go index 8faf728..d017c5c 100644 --- a/query.go +++ b/query.go @@ -7,6 +7,7 @@ import ( "github.com/goccy/go-json" "github.com/gookit/goutil" "github.com/gookit/goutil/strutil" + libpack_logger "github.com/lukaszraczylo/go-simple-graphql/logging" ) var jsonBufferPool = sync.Pool{ @@ -22,7 +23,10 @@ func (b *BaseClient) convertToJSON(v any) []byte { *jsonBuffer = (*jsonBuffer)[:0] jsonData, err := json.Marshal(v) if err != nil { - b.Logger.Error("Can't convert to JSON", map[string]interface{}{"error": err.Error()}) + b.Logger.Error(&libpack_logger.LogMessage{ + Message: "Can't convert to JSON", + Pairs: map[string]interface{}{"error": err.Error()}, + }) return nil } *jsonBuffer = append(*jsonBuffer, jsonData...) @@ -42,7 +46,10 @@ func (b *BaseClient) compileQuery(queryPartials ...any) *Query { } if query == "" { - b.Logger.Error("Can't compile query", map[string]interface{}{"error": "query is empty"}) + b.Logger.Error(&libpack_logger.LogMessage{ + Message: "Can't compile query", + Pairs: map[string]interface{}{"error": "query is empty"}, + }) return nil } @@ -57,10 +64,16 @@ func (b *BaseClient) compileQuery(queryPartials ...any) *Query { func (b *BaseClient) Query(query string, variables map[string]interface{}, headers map[string]interface{}) (any, error) { compiledQuery := b.compileQuery(query, variables) if compiledQuery.JsonQuery == nil { - b.Logger.Error("Can't compile query", map[string]interface{}{"error": "query is empty"}) + b.Logger.Error(&libpack_logger.LogMessage{ + Message: "Can't compile query", + Pairs: map[string]interface{}{"error": "query is empty"}, + }) return nil, fmt.Errorf("can't compile query") } - b.Logger.Debug("Compiled query", map[string]interface{}{"query": compiledQuery}) + b.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Compiled query", + Pairs: map[string]interface{}{"query": compiledQuery}, + }) enableCache, enableRetries, recompileRequired := compiledQuery.parseHeadersAndVariables(headers) if recompileRequired { @@ -69,17 +82,29 @@ func (b *BaseClient) Query(query string, variables map[string]interface{}, heade var queryHash string if (enableCache || b.cache_global) && strutil.HasPrefix(compiledQuery.Query, "query") { - b.Logger.Debug("Cache enabled", nil) + b.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Cache enabled", + Pairs: nil, + }) queryHash = calculateHash(compiledQuery) if cachedValue := b.cacheLookup(queryHash); cachedValue != nil { - b.Logger.Debug("Cache hit", map[string]interface{}{"query": compiledQuery}) + b.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Cache hit", + Pairs: map[string]interface{}{"query": compiledQuery}, + }) return cachedValue, nil } - b.Logger.Debug("Cache miss", map[string]interface{}{"query": compiledQuery}) + b.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Cache miss", + Pairs: map[string]interface{}{"query": compiledQuery}, + }) } if enableRetries || b.retries_enable { - b.Logger.Debug("Retries enabled", nil) + b.Logger.Debug(&libpack_logger.LogMessage{ + Message: "Retries enabled", + Pairs: nil, + }) } q := &QueryExecutor{ @@ -97,7 +122,10 @@ func (b *BaseClient) Query(query string, variables map[string]interface{}, heade rv, err := q.executeQuery() if err != nil { - b.Logger.Error("Error executing query", map[string]interface{}{"error": err.Error()}) + b.Logger.Error(&libpack_logger.LogMessage{ + Message: "Error executing query", + Pairs: map[string]interface{}{"error": err.Error()}, + }) return nil, err } diff --git a/structs.go b/structs.go index 9fd2509..68127e6 100644 --- a/structs.go +++ b/structs.go @@ -10,7 +10,7 @@ import ( type BaseClient struct { cache *cache.Cache - Logger *logging.LogConfig + Logger *logging.Logger client *http.Client endpoint string responseType string From 40af4fee5f07548d3efe80823682e74cd700a865 Mon Sep 17 00:00:00 2001 From: Lukasz Raczylo Date: Fri, 28 Jun 2024 09:06:48 +0100 Subject: [PATCH 3/3] fixup! Move to improved logging library. --- logging/logger.go | 204 +++++++++++++++++++++++++++++++++++ logging/logger_bench_test.go | 140 ++++++++++++++++++++++++ logging/logger_suite_test.go | 31 ++++++ logging/logger_test.go | 182 +++++++++++++++++++++++++++++++ 4 files changed, 557 insertions(+) create mode 100644 logging/logger.go create mode 100644 logging/logger_bench_test.go create mode 100644 logging/logger_suite_test.go create mode 100644 logging/logger_test.go diff --git a/logging/logger.go b/logging/logger.go new file mode 100644 index 0000000..7b1a964 --- /dev/null +++ b/logging/logger.go @@ -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) +} diff --git a/logging/logger_bench_test.go b/logging/logger_bench_test.go new file mode 100644 index 0000000..9d92425 --- /dev/null +++ b/logging/logger_bench_test.go @@ -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) + } +} diff --git a/logging/logger_suite_test.go b/logging/logger_suite_test.go new file mode 100644 index 0000000..965e7f4 --- /dev/null +++ b/logging/logger_suite_test.go @@ -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)) +} diff --git a/logging/logger_test.go b/logging/logger_test.go new file mode 100644 index 0000000..92d04a9 --- /dev/null +++ b/logging/logger_test.go @@ -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)) +}