From 28b73ae09f99fa255dfd7e00dd3f2056237ab94f Mon Sep 17 00:00:00 2001 From: Neur0toxine Date: Fri, 7 Jun 2024 17:55:45 +0300 Subject: [PATCH] fix tests, update for logging --- core/healthcheck/processor_test.go | 82 ++- core/job_manager_test.go | 2 +- core/logger/api_client_adapter.go | 22 +- core/logger/api_client_adapter_test.go | 40 ++ core/logger/attrs.go | 66 +- core/logger/buffer_logger_test.go | 263 ++++++++ core/logger/bufferpool.go | 29 + core/logger/default.go | 26 + core/logger/json_with_context_encoder.go | 638 ++++++++++++++++++ core/logger/mg_transport_client_adapter.go | 45 +- .../mg_transport_client_adapter_test.go | 43 ++ core/logger/nil.go | 2 + core/logger/pool.go | 57 ++ core/logger/writer_adapter.go | 1 + core/logger/zabbix_collector_adapter.go | 17 +- core/logger/zap.go | 2 +- .../util/httputil/http_client_builder_test.go | 2 +- core/util/testutil/buffer_logger.go | 4 +- core/util/testutil/buffer_logger_test.go | 9 +- core/util/testutil/json_record_scanner.go | 51 ++ .../util/testutil/json_record_scanner_test.go | 107 +++ core/util/utils_test.go | 2 +- go.mod | 5 +- go.sum | 2 + 24 files changed, 1470 insertions(+), 47 deletions(-) create mode 100644 core/logger/api_client_adapter_test.go create mode 100644 core/logger/buffer_logger_test.go create mode 100644 core/logger/bufferpool.go create mode 100644 core/logger/json_with_context_encoder.go create mode 100644 core/logger/mg_transport_client_adapter_test.go create mode 100644 core/logger/pool.go create mode 100644 core/util/testutil/json_record_scanner.go create mode 100644 core/util/testutil/json_record_scanner_test.go diff --git a/core/healthcheck/processor_test.go b/core/healthcheck/processor_test.go index 0492454..e990629 100644 --- a/core/healthcheck/processor_test.go +++ b/core/healthcheck/processor_test.go @@ -45,7 +45,7 @@ func (t *CounterProcessorTest) localizer() NotifyMessageLocalizer { } func (t *CounterProcessorTest) new( - nf NotifyFunc, pr ConnectionDataProvider, noLocalizer ...bool) (Processor, testutil.BufferedLogger) { + nf NotifyFunc, pr ConnectionDataProvider, noLocalizer ...bool) (Processor, *testutil.JSONRecordScanner) { loc := t.localizer() if len(noLocalizer) > 0 && noLocalizer[0] { loc = nil @@ -61,7 +61,7 @@ func (t *CounterProcessorTest) new( FailureThreshold: DefaultFailureThreshold, MinRequests: DefaultMinRequests, Debug: true, - }, log + }, testutil.NewJSONRecordScanner(log) } func (t *CounterProcessorTest) notifier(err ...error) *notifierMock { @@ -95,8 +95,12 @@ func (t *CounterProcessorTest) Test_FailureProcessed() { p.Process(1, c) c.AssertExpectations(t.T()) - t.Assert().Contains(log.String(), "skipping counter because its failure is already processed") - t.Assert().Contains(log.String(), `"counterId": 1`) + + logs, err := log.ScanAll() + t.Require().NoError(err) + t.Require().Len(logs, 1) + t.Assert().Contains(logs[0].Message, "skipping counter because its failure is already processed") + t.Assert().Equal(float64(1), logs[0].Context["counterId"]) } func (t *CounterProcessorTest) Test_CounterFailed_CannotFindConnection() { @@ -108,8 +112,12 @@ func (t *CounterProcessorTest) Test_CounterFailed_CannotFindConnection() { p.Process(1, c) c.AssertExpectations(t.T()) - t.Assert().Contains(log.String(), "cannot find connection data for counter") - t.Assert().Contains(log.String(), `"counterId": 1`) + + logs, err := log.ScanAll() + t.Require().NoError(err) + t.Require().Len(logs, 1) + t.Assert().Contains(logs[0].Message, "cannot find connection data for counter") + t.Assert().Equal(float64(1), logs[0].Context["counterId"]) } func (t *CounterProcessorTest) Test_CounterFailed_ErrWhileNotifying() { @@ -123,10 +131,14 @@ func (t *CounterProcessorTest) Test_CounterFailed_ErrWhileNotifying() { p.Process(1, c) c.AssertExpectations(t.T()) - t.Assert().Contains(log.String(), "cannot send notification for counter") - t.Assert().Contains(log.String(), `"counterId": 1`) - t.Assert().Contains(log.String(), `"error": "http status code: 500"`) - t.Assert().Contains(log.String(), `"failureMessage": "error message"`) + + logs, err := log.ScanAll() + t.Require().NoError(err) + t.Require().Len(logs, 1) + t.Assert().Contains(logs[0].Message, "cannot send notification for counter") + t.Assert().Equal(float64(1), logs[0].Context["counterId"]) + t.Assert().Equal("http status code: 500", logs[0].Context["error"]) + t.Assert().Equal("error message", logs[0].Context["failureMessage"]) t.Assert().Equal(t.apiURL, n.apiURL) t.Assert().Equal(t.apiKey, n.apiKey) t.Assert().Equal("error message", n.message) @@ -143,7 +155,10 @@ func (t *CounterProcessorTest) Test_CounterFailed_SentNotification() { p.Process(1, c) c.AssertExpectations(t.T()) - t.Assert().Empty(log.String()) + + logs, err := log.ScanAll() + t.Require().NoError(err) + t.Require().Len(logs, 0) t.Assert().Equal(t.apiURL, n.apiURL) t.Assert().Equal(t.apiKey, n.apiKey) t.Assert().Equal("error message", n.message) @@ -159,8 +174,13 @@ func (t *CounterProcessorTest) Test_TooFewRequests() { p.Process(1, c) c.AssertExpectations(t.T()) - t.Assert().Contains(log.String(), - fmt.Sprintf(`skipping counter because it has too few requests {"counterId": %d, "minRequests": %d}`, 1, DefaultMinRequests)) + + logs, err := log.ScanAll() + t.Require().NoError(err) + t.Require().Len(logs, 1) + t.Assert().Contains(logs[0].Message, "skipping counter because it has too few requests") + t.Assert().Equal(float64(1), logs[0].Context["counterId"]) + t.Assert().Equal(float64(DefaultMinRequests), logs[0].Context["minRequests"]) } func (t *CounterProcessorTest) Test_ThresholdNotPassed() { @@ -175,7 +195,10 @@ func (t *CounterProcessorTest) Test_ThresholdNotPassed() { p.Process(1, c) c.AssertExpectations(t.T()) - t.Assert().Empty(log.String()) + + logs, err := log.ScanAll() + t.Require().NoError(err) + t.Require().Len(logs, 0) t.Assert().Empty(n.message) } @@ -190,7 +213,10 @@ func (t *CounterProcessorTest) Test_ThresholdPassed_AlreadyProcessed() { p.Process(1, c) c.AssertExpectations(t.T()) - t.Assert().Empty(log.String()) + + logs, err := log.ScanAll() + t.Require().NoError(err) + t.Require().Len(logs, 0) t.Assert().Empty(n.message) } @@ -205,8 +231,12 @@ func (t *CounterProcessorTest) Test_ThresholdPassed_NoConnectionFound() { p.Process(1, c) c.AssertExpectations(t.T()) - t.Assert().Contains(log.String(), "cannot find connection data for counter") - t.Assert().Contains(log.String(), `"counterId": 1`) + + logs, err := log.ScanAll() + t.Require().NoError(err) + t.Require().Len(logs, 1) + t.Assert().Contains(logs[0].Message, "cannot find connection data for counter") + t.Assert().Equal(float64(1), logs[0].Context["counterId"]) t.Assert().Empty(n.message) } @@ -224,7 +254,13 @@ func (t *CounterProcessorTest) Test_ThresholdPassed_NotifyingError() { p.Process(1, c) c.AssertExpectations(t.T()) - t.Assert().Contains(log.String(), `cannot send notification for counter {"counterId": 1, "error": "unknown error", "failureMessage": ""}`) + + logs, err := log.ScanAll() + t.Require().NoError(err) + t.Require().Len(logs, 1) + t.Assert().Contains(logs[0].Message, "cannot send notification for counter") + t.Assert().Equal(float64(1), logs[0].Context["counterId"]) + t.Assert().Equal("unknown error", logs[0].Context["error"]) t.Assert().Equal(`default error [{"Name":"MockedCounter"}]`, n.message) } @@ -241,7 +277,10 @@ func (t *CounterProcessorTest) Test_ThresholdPassed_NotificationSent() { p.Process(1, c) c.AssertExpectations(t.T()) - t.Assert().Empty(log.String()) + + logs, err := log.ScanAll() + t.Require().NoError(err) + t.Require().Len(logs, 0) t.Assert().Equal(`default error [{"Name":"MockedCounter"}]`, n.message) } @@ -258,7 +297,10 @@ func (t *CounterProcessorTest) Test_ThresholdPassed_NotificationSent_NoLocalizer p.Process(1, c) c.AssertExpectations(t.T()) - t.Assert().Empty(log.String()) + + logs, err := log.ScanAll() + t.Require().NoError(err) + t.Require().Len(logs, 0) t.Assert().Equal(`default error`, n.message) } diff --git a/core/job_manager_test.go b/core/job_manager_test.go index b6cce5a..40ed2a6 100644 --- a/core/job_manager_test.go +++ b/core/job_manager_test.go @@ -436,7 +436,7 @@ func (t *JobManagerTest) WaitForJob() bool { func (t *JobManagerTest) Test_SetLogger() { t.manager.logger = nil - t.manager.SetLogger(logger.NewDefault("console", true)) + t.manager.SetLogger(logger.NewDefault("json", true)) assert.IsType(t.T(), &logger.Default{}, t.manager.logger) t.manager.SetLogger(nil) diff --git a/core/logger/api_client_adapter.go b/core/logger/api_client_adapter.go index 7951336..1cb7d4c 100644 --- a/core/logger/api_client_adapter.go +++ b/core/logger/api_client_adapter.go @@ -2,10 +2,16 @@ package logger import ( "fmt" + "go.uber.org/zap" retailcrm "github.com/retailcrm/api-client-go/v2" ) +const ( + apiDebugLogReq = "API Request: %s %s" + apiDebugLogResp = "API Response: %s" +) + type apiClientAdapter struct { logger Logger } @@ -17,5 +23,19 @@ func APIClientAdapter(logger Logger) retailcrm.BasicLogger { // Printf data in the log using Debug method. func (l *apiClientAdapter) Printf(format string, v ...interface{}) { - l.logger.Debug(fmt.Sprintf(format, v...)) + switch format { + case apiDebugLogReq: + var url, key string + if len(v) > 0 { + url = fmt.Sprint(v[0]) + } + if len(v) > 1 { + key = fmt.Sprint(v[1]) + } + l.logger.Debug("API Request", zap.String("url", url), zap.String("key", key)) + case apiDebugLogResp: + l.logger.Debug("API Response", Body(v[0])) + default: + l.logger.Debug(fmt.Sprintf(format, v...)) + } } diff --git a/core/logger/api_client_adapter_test.go b/core/logger/api_client_adapter_test.go new file mode 100644 index 0000000..4ad51e7 --- /dev/null +++ b/core/logger/api_client_adapter_test.go @@ -0,0 +1,40 @@ +package logger + +import ( + "github.com/h2non/gock" + retailcrm "github.com/retailcrm/api-client-go/v2" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "net/http" + "testing" +) + +func TestAPIClientAdapter(t *testing.T) { + log := newJSONBufferedLogger() + client := retailcrm.New("https://example.com", "test_key").WithLogger(APIClientAdapter(log.Logger())) + client.Debug = true + + defer gock.Off() + gock.New("https://example.com"). + Get("/api/credentials"). + Reply(http.StatusOK). + JSON(retailcrm.CredentialResponse{Success: true}) + + _, _, err := client.APICredentials() + require.NoError(t, err) + + entries, err := log.ScanAll() + require.NoError(t, err) + require.Len(t, entries, 2) + + assert.Equal(t, "DEBUG", entries[0].LevelName) + assert.True(t, entries[0].DateTime.Valid) + assert.Equal(t, "API Request", entries[0].Message) + assert.Equal(t, "test_key", entries[0].Context["key"]) + assert.Equal(t, "https://example.com/api/credentials", entries[0].Context["url"]) + + assert.Equal(t, "DEBUG", entries[1].LevelName) + assert.True(t, entries[1].DateTime.Valid) + assert.Equal(t, "API Response", entries[1].Message) + assert.Equal(t, map[string]interface{}{"success": true}, entries[1].Context["body"]) +} diff --git a/core/logger/attrs.go b/core/logger/attrs.go index 17bd746..73de78d 100644 --- a/core/logger/attrs.go +++ b/core/logger/attrs.go @@ -2,24 +2,44 @@ package logger import ( "fmt" + json "github.com/goccy/go-json" + "io" "net/http" "go.uber.org/zap" ) -const ( - HandlerAttr = "handler" - ConnectionAttr = "connection" - AccountAttr = "account" - CounterIDAttr = "counterId" - ErrorAttr = "error" - FailureMessageAttr = "failureMessage" - BodyAttr = "body" - HTTPMethodAttr = "method" - HTTPStatusAttr = "statusCode" - HTTPStatusNameAttr = "statusName" -) +// HandlerAttr represents the attribute name for the handler. +const HandlerAttr = "handler" +// ConnectionAttr represents the attribute name for the connection. +const ConnectionAttr = "connection" + +// AccountAttr represents the attribute name for the account. +const AccountAttr = "account" + +// CounterIDAttr represents the attribute name for the counter ID. +const CounterIDAttr = "counterId" + +// ErrorAttr represents the attribute name for an error. +const ErrorAttr = "error" + +// FailureMessageAttr represents the attribute name for a failure message. +const FailureMessageAttr = "failureMessage" + +// BodyAttr represents the attribute name for the request body. +const BodyAttr = "body" + +// HTTPMethodAttr represents the attribute name for the HTTP method. +const HTTPMethodAttr = "method" + +// HTTPStatusAttr represents the attribute name for the HTTP status code. +const HTTPStatusAttr = "statusCode" + +// HTTPStatusNameAttr represents the attribute name for the HTTP status name. +const HTTPStatusNameAttr = "statusName" + +// Err returns a zap.Field with the given error value. func Err(err any) zap.Field { if err == nil { return zap.String(ErrorAttr, "") @@ -27,24 +47,46 @@ func Err(err any) zap.Field { return zap.Any(ErrorAttr, err) } +// Handler returns a zap.Field with the given handler name. func Handler(name string) zap.Field { return zap.String(HandlerAttr, name) } +// HTTPStatusCode returns a zap.Field with the given HTTP status code. func HTTPStatusCode(code int) zap.Field { return zap.Int(HTTPStatusAttr, code) } +// HTTPStatusName returns a zap.Field with the given HTTP status name. func HTTPStatusName(code int) zap.Field { return zap.String(HTTPStatusNameAttr, http.StatusText(code)) } +// Body returns a zap.Field with the given request body value. func Body(val any) zap.Field { switch item := val.(type) { case string: + var m map[string]interface{} + if err := json.Unmarshal([]byte(item), &m); err == nil { + return zap.Any(BodyAttr, m) + } return zap.String(BodyAttr, item) case []byte: + var m interface{} + if err := json.Unmarshal(item, &m); err == nil { + return zap.Any(BodyAttr, m) + } return zap.String(BodyAttr, string(item)) + case io.Reader: + data, err := io.ReadAll(item) + if err != nil { + return zap.String(BodyAttr, fmt.Sprintf("%#v", val)) + } + var m interface{} + if err := json.Unmarshal(data, &m); err == nil { + return zap.Any(BodyAttr, m) + } + return zap.String(BodyAttr, string(data)) default: return zap.String(BodyAttr, fmt.Sprintf("%#v", val)) } diff --git a/core/logger/buffer_logger_test.go b/core/logger/buffer_logger_test.go new file mode 100644 index 0000000..7c0b193 --- /dev/null +++ b/core/logger/buffer_logger_test.go @@ -0,0 +1,263 @@ +package logger + +import ( + "bufio" + "bytes" + "encoding/json" + "github.com/guregu/null/v5" + "io" + "os" + "sync" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +type logRecord struct { + LevelName string `json:"level_name"` + DateTime null.Time `json:"datetime"` + Caller string `json:"caller"` + Message string `json:"message"` + Handler string `json:"handler,omitempty"` + Connection string `json:"connection,omitempty"` + Account string `json:"account,omitempty"` + Context map[string]interface{} `json:"context,omitempty"` +} + +type jSONRecordScanner struct { + scan *bufio.Scanner + buf *bufferLogger +} + +func newJSONBufferedLogger() *jSONRecordScanner { + buf := newBufferLogger() + return &jSONRecordScanner{scan: bufio.NewScanner(buf), buf: buf} +} + +func (s *jSONRecordScanner) ScanAll() ([]logRecord, error) { + var entries []logRecord + for s.scan.Scan() { + entry := logRecord{} + if err := json.Unmarshal(s.scan.Bytes(), &entry); err != nil { + return entries, err + } + entries = append(entries, entry) + } + return entries, nil +} + +func (s *jSONRecordScanner) Logger() Logger { + return s.buf +} + +// bufferLogger is an implementation of the BufferedLogger. +type bufferLogger struct { + Default + buf lockableBuffer +} + +// NewBufferedLogger returns new BufferedLogger instance. +func newBufferLogger() *bufferLogger { + bl := &bufferLogger{} + bl.Logger = zap.New( + zapcore.NewCore( + NewJSONWithContextEncoder( + EncoderConfigJSON()), zap.CombineWriteSyncers(os.Stdout, os.Stderr, &bl.buf), zapcore.DebugLevel)) + return bl +} + +func (l *bufferLogger) With(fields ...zapcore.Field) Logger { + return &bufferLogger{ + Default: Default{ + Logger: l.Logger.With(fields...), + }, + } +} + +func (l *bufferLogger) WithLazy(fields ...zapcore.Field) Logger { + return &bufferLogger{ + Default: Default{ + Logger: l.Logger.WithLazy(fields...), + }, + } +} + +func (l *bufferLogger) ForHandler(handler any) Logger { + return l.WithLazy(zap.Any(HandlerAttr, handler)) +} + +func (l *bufferLogger) ForConnection(conn any) Logger { + return l.WithLazy(zap.Any(ConnectionAttr, conn)) +} + +func (l *bufferLogger) ForAccount(acc any) Logger { + return l.WithLazy(zap.Any(AccountAttr, acc)) +} + +// Read bytes from the logger buffer. io.Reader implementation. +func (l *bufferLogger) Read(p []byte) (n int, err error) { + return l.buf.Read(p) +} + +// String contents of the logger buffer. fmt.Stringer implementation. +func (l *bufferLogger) String() string { + return l.buf.String() +} + +// Bytes is a shorthand for the underlying bytes.Buffer method. Returns byte slice with the buffer contents. +func (l *bufferLogger) Bytes() []byte { + return l.buf.Bytes() +} + +// Reset is a shorthand for the underlying bytes.Buffer method. It will reset buffer contents. +func (l *bufferLogger) Reset() { + l.buf.Reset() +} + +type lockableBuffer struct { + buf bytes.Buffer + rw sync.RWMutex +} + +func (b *lockableBuffer) Bytes() []byte { + defer b.rw.RUnlock() + b.rw.RLock() + return b.buf.Bytes() +} + +func (b *lockableBuffer) AvailableBuffer() []byte { + defer b.rw.RUnlock() + b.rw.RLock() + return b.buf.AvailableBuffer() +} + +func (b *lockableBuffer) String() string { + defer b.rw.RUnlock() + b.rw.RLock() + return b.buf.String() +} + +func (b *lockableBuffer) Len() int { + defer b.rw.RUnlock() + b.rw.RLock() + return b.buf.Len() +} + +func (b *lockableBuffer) Cap() int { + defer b.rw.RUnlock() + b.rw.RLock() + return b.buf.Cap() +} + +func (b *lockableBuffer) Available() int { + defer b.rw.RUnlock() + b.rw.RLock() + return b.buf.Available() +} + +func (b *lockableBuffer) Truncate(n int) { + defer b.rw.Unlock() + b.rw.Lock() + b.buf.Truncate(n) +} + +func (b *lockableBuffer) Reset() { + defer b.rw.Unlock() + b.rw.Lock() + b.buf.Reset() +} + +func (b *lockableBuffer) Grow(n int) { + defer b.rw.Unlock() + b.rw.Lock() + b.buf.Grow(n) +} + +func (b *lockableBuffer) Write(p []byte) (n int, err error) { + defer b.rw.Unlock() + b.rw.Lock() + return b.buf.Write(p) +} + +func (b *lockableBuffer) WriteString(s string) (n int, err error) { + defer b.rw.Unlock() + b.rw.Lock() + return b.buf.WriteString(s) +} + +func (b *lockableBuffer) ReadFrom(r io.Reader) (n int64, err error) { + defer b.rw.Unlock() + b.rw.Lock() + return b.buf.ReadFrom(r) +} + +func (b *lockableBuffer) WriteTo(w io.Writer) (n int64, err error) { + defer b.rw.Unlock() + b.rw.Lock() + return b.buf.WriteTo(w) +} + +func (b *lockableBuffer) WriteByte(c byte) error { + defer b.rw.Unlock() + b.rw.Lock() + return b.buf.WriteByte(c) +} + +func (b *lockableBuffer) WriteRune(r rune) (n int, err error) { + defer b.rw.Unlock() + b.rw.Lock() + return b.buf.WriteRune(r) +} + +func (b *lockableBuffer) Read(p []byte) (n int, err error) { + defer b.rw.Unlock() + b.rw.Lock() + return b.buf.Read(p) +} + +func (b *lockableBuffer) Next(n int) []byte { + defer b.rw.Unlock() + b.rw.Lock() + return b.buf.Next(n) +} + +func (b *lockableBuffer) ReadByte() (byte, error) { + defer b.rw.Unlock() + b.rw.Lock() + return b.buf.ReadByte() +} + +func (b *lockableBuffer) ReadRune() (r rune, size int, err error) { + defer b.rw.Unlock() + b.rw.Lock() + return b.buf.ReadRune() +} + +func (b *lockableBuffer) UnreadRune() error { + defer b.rw.Unlock() + b.rw.Lock() + return b.buf.UnreadRune() +} + +func (b *lockableBuffer) UnreadByte() error { + defer b.rw.Unlock() + b.rw.Lock() + return b.buf.UnreadByte() +} + +func (b *lockableBuffer) ReadBytes(delim byte) (line []byte, err error) { + defer b.rw.Unlock() + b.rw.Lock() + return b.buf.ReadBytes(delim) +} + +func (b *lockableBuffer) ReadString(delim byte) (line string, err error) { + defer b.rw.Unlock() + b.rw.Lock() + return b.buf.ReadString(delim) +} + +// Sync is a no-op. +func (b *lockableBuffer) Sync() error { + return nil +} diff --git a/core/logger/bufferpool.go b/core/logger/bufferpool.go new file mode 100644 index 0000000..e0a4e8b --- /dev/null +++ b/core/logger/bufferpool.go @@ -0,0 +1,29 @@ +// Copyright (c) 2016 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package logger + +import "go.uber.org/zap/buffer" + +var ( + _pool = buffer.NewPool() + // GetBufferPool retrieves a buffer from the pool, creating one if necessary. + GetBufferPool = _pool.Get +) diff --git a/core/logger/default.go b/core/logger/default.go index 8b1bb1f..8ec6fc7 100644 --- a/core/logger/default.go +++ b/core/logger/default.go @@ -7,59 +7,85 @@ import ( "go.uber.org/zap/zapcore" ) +// Logger is a logging interface. type Logger interface { + // With adds fields to the logger and returns a new logger with those fields. With(fields ...zap.Field) Logger + // WithLazy adds fields to the logger lazily and returns a new logger with those fields. WithLazy(fields ...zap.Field) Logger + // Level returns the logging level of the logger. Level() zapcore.Level + // Check checks if the log message meets the given level. Check(lvl zapcore.Level, msg string) *zapcore.CheckedEntry + // Log logs a message with the given level and fields. Log(lvl zapcore.Level, msg string, fields ...zap.Field) + // Debug logs a debug-level message with the given fields. Debug(msg string, fields ...zap.Field) + // Info logs an info-level message with the given fields. Info(msg string, fields ...zap.Field) + // Warn logs a warning-level message with the given fields. Warn(msg string, fields ...zap.Field) + // Error logs an error-level message with the given fields. Error(msg string, fields ...zap.Field) + // DPanic logs a debug-panic-level message with the given fields and panics if the logger's panic level is set to a non-zero value. DPanic(msg string, fields ...zap.Field) + // Panic logs a panic-level message with the given fields and panics immediately. Panic(msg string, fields ...zap.Field) + // Fatal logs a fatal-level message with the given fields, then calls os.Exit(1). Fatal(msg string, fields ...zap.Field) + // ForHandler returns a new logger that is associated with the given handler. ForHandler(handler any) Logger + // ForConnection returns a new logger that is associated with the given connection. ForConnection(conn any) Logger + // ForAccount returns a new logger that is associated with the given account. ForAccount(acc any) Logger + // Sync returns an error if there's a problem writing log messages to disk, or nil if all writes were successful. Sync() error } +// Default is a default logger implementation. type Default struct { *zap.Logger } +// NewDefault creates a new default logger with the given format and debug level. func NewDefault(format string, debug bool) Logger { return &Default{ Logger: NewZap(format, debug), } } +// With adds fields to the logger and returns a new logger with those fields. func (l *Default) With(fields ...zap.Field) Logger { return l.clone(l.Logger.With(fields...)) } +// WithLazy adds fields to the logger lazily and returns a new logger with those fields. func (l *Default) WithLazy(fields ...zap.Field) Logger { return l.clone(l.Logger.WithLazy(fields...)) } +// ForHandler returns a new logger that is associated with the given handler. func (l *Default) ForHandler(handler any) Logger { return l.WithLazy(zap.Any(HandlerAttr, handler)) } +// ForConnection returns a new logger that is associated with the given connection. func (l *Default) ForConnection(conn any) Logger { return l.WithLazy(zap.Any(ConnectionAttr, conn)) } +// ForAccount returns a new logger that is associated with the given account. func (l *Default) ForAccount(acc any) Logger { return l.WithLazy(zap.Any(AccountAttr, acc)) } +// clone creates a copy of the given logger. func (l *Default) clone(log *zap.Logger) Logger { return &Default{Logger: log} } +// AnyZapFields converts an array of values to zap fields. func AnyZapFields(args []interface{}) []zap.Field { fields := make([]zap.Field, len(args)) for i := 0; i < len(fields); i++ { diff --git a/core/logger/json_with_context_encoder.go b/core/logger/json_with_context_encoder.go new file mode 100644 index 0000000..cb377e7 --- /dev/null +++ b/core/logger/json_with_context_encoder.go @@ -0,0 +1,638 @@ +// Copyright (c) 2016 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package logger + +import ( + "encoding/base64" + "encoding/json" + "fmt" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "io" + "math" + "time" + "unicode/utf8" + + "go.uber.org/zap/buffer" +) + +// For JSON-escaping; see jsonWithContextEncoder.safeAddString below. +const _hex = "0123456789abcdef" + +var _jsonWithContextPool = NewPool(func() *jsonWithContextEncoder { + return &jsonWithContextEncoder{} +}) + +func init() { + err := zap.RegisterEncoder("json-with-context", func(config zapcore.EncoderConfig) (zapcore.Encoder, error) { + return NewJSONWithContextEncoder(config), nil + }) + if err != nil { + panic(err) + } +} + +func putJSONWithContextEncoder(enc *jsonWithContextEncoder) { + if enc.reflectBuf != nil { + enc.reflectBuf.Free() + } + enc.EncoderConfig = nil + enc.buf = nil + enc.spaced = false + enc.openNamespaces = 0 + enc.reflectBuf = nil + enc.reflectEnc = nil + _jsonWithContextPool.Put(enc) +} + +type jsonWithContextEncoder struct { + *zapcore.EncoderConfig + buf *buffer.Buffer + spaced bool // include spaces after colons and commas + openNamespaces int + + // for encoding generic values by reflection + reflectBuf *buffer.Buffer + reflectEnc zapcore.ReflectedEncoder +} + +// NewJSONWithContextEncoder creates a fast, low-allocation JSON encoder. The encoder +// appropriately escapes all field keys and values. +// +// Note that the encoder doesn't deduplicate keys, so it's possible to produce +// a message like +// +// {"foo":"bar","foo":"baz"} +// +// This is permitted by the JSON specification, but not encouraged. Many +// libraries will ignore duplicate key-value pairs (typically keeping the last +// pair) when unmarshaling, but users should attempt to avoid adding duplicate +// keys. +func NewJSONWithContextEncoder(cfg zapcore.EncoderConfig) zapcore.Encoder { + return newJSONWithContextEncoder(cfg, false) +} + +func newJSONWithContextEncoder(cfg zapcore.EncoderConfig, spaced bool) *jsonWithContextEncoder { + if cfg.SkipLineEnding { + cfg.LineEnding = "" + } else if cfg.LineEnding == "" { + cfg.LineEnding = zapcore.DefaultLineEnding + } + + // If no EncoderConfig.NewReflectedEncoder is provided by the user, then use default + if cfg.NewReflectedEncoder == nil { + cfg.NewReflectedEncoder = defaultReflectedEncoder + } + + return &jsonWithContextEncoder{ + EncoderConfig: &cfg, + buf: GetBufferPool(), + spaced: spaced, + } +} + +func defaultReflectedEncoder(w io.Writer) zapcore.ReflectedEncoder { + enc := json.NewEncoder(w) + // For consistency with our custom JSON encoder. + enc.SetEscapeHTML(false) + return enc +} + +func (enc *jsonWithContextEncoder) AddArray(key string, arr zapcore.ArrayMarshaler) error { + enc.addKey(key) + return enc.AppendArray(arr) +} + +func (enc *jsonWithContextEncoder) AddObject(key string, obj zapcore.ObjectMarshaler) error { + enc.addKey(key) + return enc.AppendObject(obj) +} + +func (enc *jsonWithContextEncoder) AddBinary(key string, val []byte) { + enc.AddString(key, base64.StdEncoding.EncodeToString(val)) +} + +func (enc *jsonWithContextEncoder) AddByteString(key string, val []byte) { + enc.addKey(key) + enc.AppendByteString(val) +} + +func (enc *jsonWithContextEncoder) AddBool(key string, val bool) { + enc.addKey(key) + enc.AppendBool(val) +} + +func (enc *jsonWithContextEncoder) AddComplex128(key string, val complex128) { + enc.addKey(key) + enc.AppendComplex128(val) +} + +func (enc *jsonWithContextEncoder) AddComplex64(key string, val complex64) { + enc.addKey(key) + enc.AppendComplex64(val) +} + +func (enc *jsonWithContextEncoder) AddDuration(key string, val time.Duration) { + enc.addKey(key) + enc.AppendDuration(val) +} + +func (enc *jsonWithContextEncoder) AddFloat64(key string, val float64) { + enc.addKey(key) + enc.AppendFloat64(val) +} + +func (enc *jsonWithContextEncoder) AddFloat32(key string, val float32) { + enc.addKey(key) + enc.AppendFloat32(val) +} + +func (enc *jsonWithContextEncoder) AddInt64(key string, val int64) { + enc.addKey(key) + enc.AppendInt64(val) +} + +func (enc *jsonWithContextEncoder) resetReflectBuf() { + if enc.reflectBuf == nil { + enc.reflectBuf = GetBufferPool() + enc.reflectEnc = enc.NewReflectedEncoder(enc.reflectBuf) + } else { + enc.reflectBuf.Reset() + } +} + +var nullLiteralBytes = []byte("null") + +// Only invoke the standard JSON encoder if there is actually something to +// encode; otherwise write JSON null literal directly. +func (enc *jsonWithContextEncoder) encodeReflected(obj interface{}) ([]byte, error) { + if obj == nil { + return nullLiteralBytes, nil + } + enc.resetReflectBuf() + if err := enc.reflectEnc.Encode(obj); err != nil { + return nil, err + } + enc.reflectBuf.TrimNewline() + return enc.reflectBuf.Bytes(), nil +} + +func (enc *jsonWithContextEncoder) AddReflected(key string, obj interface{}) error { + valueBytes, err := enc.encodeReflected(obj) + if err != nil { + return err + } + enc.addKey(key) + _, err = enc.buf.Write(valueBytes) + return err +} + +func (enc *jsonWithContextEncoder) OpenNamespace(key string) { + enc.addKey(key) + enc.buf.AppendByte('{') + enc.openNamespaces++ +} + +func (enc *jsonWithContextEncoder) AddString(key, val string) { + enc.addKey(key) + enc.AppendString(val) +} + +func (enc *jsonWithContextEncoder) AddTime(key string, val time.Time) { + enc.addKey(key) + enc.AppendTime(val) +} + +func (enc *jsonWithContextEncoder) AddUint64(key string, val uint64) { + enc.addKey(key) + enc.AppendUint64(val) +} + +func (enc *jsonWithContextEncoder) AppendArray(arr zapcore.ArrayMarshaler) error { + enc.addElementSeparator() + enc.buf.AppendByte('[') + err := arr.MarshalLogArray(enc) + enc.buf.AppendByte(']') + return err +} + +func (enc *jsonWithContextEncoder) AppendObject(obj zapcore.ObjectMarshaler) error { + // Close ONLY new openNamespaces that are created during + // AppendObject(). + old := enc.openNamespaces + enc.openNamespaces = 0 + enc.addElementSeparator() + enc.buf.AppendByte('{') + err := obj.MarshalLogObject(enc) + enc.buf.AppendByte('}') + enc.closeOpenNamespaces() + enc.openNamespaces = old + return err +} + +func (enc *jsonWithContextEncoder) AppendBool(val bool) { + enc.addElementSeparator() + enc.buf.AppendBool(val) +} + +func (enc *jsonWithContextEncoder) AppendByteString(val []byte) { + enc.addElementSeparator() + enc.buf.AppendByte('"') + enc.safeAddByteString(val) + enc.buf.AppendByte('"') +} + +// appendComplex appends the encoded form of the provided complex128 value. +// precision specifies the encoding precision for the real and imaginary +// components of the complex number. +func (enc *jsonWithContextEncoder) appendComplex(val complex128, precision int) { + enc.addElementSeparator() + // Cast to a platform-independent, fixed-size type. + r, i := float64(real(val)), float64(imag(val)) + enc.buf.AppendByte('"') + // Because we're always in a quoted string, we can use strconv without + // special-casing NaN and +/-Inf. + enc.buf.AppendFloat(r, precision) + // If imaginary part is less than 0, minus (-) sign is added by default + // by AppendFloat. + if i >= 0 { + enc.buf.AppendByte('+') + } + enc.buf.AppendFloat(i, precision) + enc.buf.AppendByte('i') + enc.buf.AppendByte('"') +} + +func (enc *jsonWithContextEncoder) AppendDuration(val time.Duration) { + cur := enc.buf.Len() + if e := enc.EncodeDuration; e != nil { + e(val, enc) + } + if cur == enc.buf.Len() { + // User-supplied EncodeDuration is a no-op. Fall back to nanoseconds to keep + // JSON valid. + enc.AppendInt64(int64(val)) + } +} + +func (enc *jsonWithContextEncoder) AppendInt64(val int64) { + enc.addElementSeparator() + enc.buf.AppendInt(val) +} + +func (enc *jsonWithContextEncoder) AppendReflected(val interface{}) error { + valueBytes, err := enc.encodeReflected(val) + if err != nil { + return err + } + enc.addElementSeparator() + _, err = enc.buf.Write(valueBytes) + return err +} + +func (enc *jsonWithContextEncoder) AppendString(val string) { + enc.addElementSeparator() + enc.buf.AppendByte('"') + enc.safeAddString(val) + enc.buf.AppendByte('"') +} + +func (enc *jsonWithContextEncoder) AppendTimeLayout(time time.Time, layout string) { + enc.addElementSeparator() + enc.buf.AppendByte('"') + enc.buf.AppendTime(time, layout) + enc.buf.AppendByte('"') +} + +func (enc *jsonWithContextEncoder) AppendTime(val time.Time) { + cur := enc.buf.Len() + if e := enc.EncodeTime; e != nil { + e(val, enc) + } + if cur == enc.buf.Len() { + // User-supplied EncodeTime is a no-op. Fall back to nanos since epoch to keep + // output JSON valid. + enc.AppendInt64(val.UnixNano()) + } +} + +func (enc *jsonWithContextEncoder) AppendUint64(val uint64) { + enc.addElementSeparator() + enc.buf.AppendUint(val) +} + +func (enc *jsonWithContextEncoder) AddInt(k string, v int) { enc.AddInt64(k, int64(v)) } +func (enc *jsonWithContextEncoder) AddInt32(k string, v int32) { enc.AddInt64(k, int64(v)) } +func (enc *jsonWithContextEncoder) AddInt16(k string, v int16) { enc.AddInt64(k, int64(v)) } +func (enc *jsonWithContextEncoder) AddInt8(k string, v int8) { enc.AddInt64(k, int64(v)) } +func (enc *jsonWithContextEncoder) AddUint(k string, v uint) { enc.AddUint64(k, uint64(v)) } +func (enc *jsonWithContextEncoder) AddUint32(k string, v uint32) { enc.AddUint64(k, uint64(v)) } +func (enc *jsonWithContextEncoder) AddUint16(k string, v uint16) { enc.AddUint64(k, uint64(v)) } +func (enc *jsonWithContextEncoder) AddUint8(k string, v uint8) { enc.AddUint64(k, uint64(v)) } +func (enc *jsonWithContextEncoder) AddUintptr(k string, v uintptr) { enc.AddUint64(k, uint64(v)) } +func (enc *jsonWithContextEncoder) AppendComplex64(v complex64) { enc.appendComplex(complex128(v), 32) } +func (enc *jsonWithContextEncoder) AppendComplex128(v complex128) { + enc.appendComplex(complex128(v), 64) +} +func (enc *jsonWithContextEncoder) AppendFloat64(v float64) { enc.appendFloat(v, 64) } +func (enc *jsonWithContextEncoder) AppendFloat32(v float32) { enc.appendFloat(float64(v), 32) } +func (enc *jsonWithContextEncoder) AppendInt(v int) { enc.AppendInt64(int64(v)) } +func (enc *jsonWithContextEncoder) AppendInt32(v int32) { enc.AppendInt64(int64(v)) } +func (enc *jsonWithContextEncoder) AppendInt16(v int16) { enc.AppendInt64(int64(v)) } +func (enc *jsonWithContextEncoder) AppendInt8(v int8) { enc.AppendInt64(int64(v)) } +func (enc *jsonWithContextEncoder) AppendUint(v uint) { enc.AppendUint64(uint64(v)) } +func (enc *jsonWithContextEncoder) AppendUint32(v uint32) { enc.AppendUint64(uint64(v)) } +func (enc *jsonWithContextEncoder) AppendUint16(v uint16) { enc.AppendUint64(uint64(v)) } +func (enc *jsonWithContextEncoder) AppendUint8(v uint8) { enc.AppendUint64(uint64(v)) } +func (enc *jsonWithContextEncoder) AppendUintptr(v uintptr) { enc.AppendUint64(uint64(v)) } + +func (enc *jsonWithContextEncoder) Clone() zapcore.Encoder { + clone := enc.clone() + clone.buf.Write(enc.buf.Bytes()) + return clone +} + +func (enc *jsonWithContextEncoder) clone() *jsonWithContextEncoder { + clone := _jsonWithContextPool.Get() + clone.EncoderConfig = enc.EncoderConfig + clone.spaced = enc.spaced + clone.openNamespaces = enc.openNamespaces + clone.buf = GetBufferPool() + return clone +} + +func (enc *jsonWithContextEncoder) EncodeEntry(ent zapcore.Entry, fields []zapcore.Field) (*buffer.Buffer, error) { + final := enc.clone() + final.buf.AppendByte('{') + + if final.LevelKey != "" && final.EncodeLevel != nil { + final.addKey(final.LevelKey) + cur := final.buf.Len() + final.EncodeLevel(ent.Level, final) + if cur == final.buf.Len() { + // User-supplied EncodeLevel was a no-op. Fall back to strings to keep + // output JSON valid. + final.AppendString(ent.Level.String()) + } + } + if final.TimeKey != "" { + final.AddTime(final.TimeKey, ent.Time) + } + if ent.LoggerName != "" && final.NameKey != "" { + final.addKey(final.NameKey) + cur := final.buf.Len() + nameEncoder := final.EncodeName + + // if no name encoder provided, fall back to FullNameEncoder for backwards + // compatibility + if nameEncoder == nil { + nameEncoder = zapcore.FullNameEncoder + } + + nameEncoder(ent.LoggerName, final) + if cur == final.buf.Len() { + // User-supplied EncodeName was a no-op. Fall back to strings to + // keep output JSON valid. + final.AppendString(ent.LoggerName) + } + } + if ent.Caller.Defined { + if final.CallerKey != "" { + final.addKey(final.CallerKey) + cur := final.buf.Len() + final.EncodeCaller(ent.Caller, final) + if cur == final.buf.Len() { + // User-supplied EncodeCaller was a no-op. Fall back to strings to + // keep output JSON valid. + final.AppendString(ent.Caller.String()) + } + } + if final.FunctionKey != "" { + final.addKey(final.FunctionKey) + final.AppendString(ent.Caller.Function) + } + } + if final.MessageKey != "" { + final.addKey(enc.MessageKey) + final.AppendString(ent.Message) + } + if enc.buf.Len() > 0 { + final.addElementSeparator() + final.buf.Write(enc.buf.Bytes()) + } + addFields(final, fields) + final.closeOpenNamespaces() + if ent.Stack != "" && final.StacktraceKey != "" { + final.AddString(final.StacktraceKey, ent.Stack) + } + final.buf.AppendByte('}') + final.buf.AppendString(final.LineEnding) + + ret := final.buf + putJSONWithContextEncoder(final) + return ret, nil +} + +func addFields(enc zapcore.ObjectEncoder, fields []zapcore.Field) { + m := make(map[string]interface{}) + hasEntries := false + for _, f := range fields { + switch f.Key { + case HandlerAttr, ConnectionAttr, AccountAttr: + f.AddTo(enc) + default: + hasEntries = true + if f.Interface != nil { + switch t := f.Interface.(type) { + case fmt.Stringer: + m[f.Key] = t.String() + case fmt.GoStringer: + m[f.Key] = t.GoString() + case error: + m[f.Key] = t.Error() + default: + m[f.Key] = f.Interface + } + continue + } + if f.String != "" { + m[f.Key] = f.String + continue + } + m[f.Key] = f.Integer + } + } + if hasEntries { + zap.Any("context", m).AddTo(enc) + } +} + +func (enc *jsonWithContextEncoder) truncate() { + enc.buf.Reset() +} + +func (enc *jsonWithContextEncoder) closeOpenNamespaces() { + for i := 0; i < enc.openNamespaces; i++ { + enc.buf.AppendByte('}') + } + enc.openNamespaces = 0 +} + +func (enc *jsonWithContextEncoder) addKey(key string) { + enc.addElementSeparator() + enc.buf.AppendByte('"') + enc.safeAddString(key) + enc.buf.AppendByte('"') + enc.buf.AppendByte(':') + if enc.spaced { + enc.buf.AppendByte(' ') + } +} + +func (enc *jsonWithContextEncoder) addElementSeparator() { + last := enc.buf.Len() - 1 + if last < 0 { + return + } + switch enc.buf.Bytes()[last] { + case '{', '[', ':', ',', ' ': + return + default: + enc.buf.AppendByte(',') + if enc.spaced { + enc.buf.AppendByte(' ') + } + } +} + +func (enc *jsonWithContextEncoder) appendFloat(val float64, bitSize int) { + enc.addElementSeparator() + switch { + case math.IsNaN(val): + enc.buf.AppendString(`"NaN"`) + case math.IsInf(val, 1): + enc.buf.AppendString(`"+Inf"`) + case math.IsInf(val, -1): + enc.buf.AppendString(`"-Inf"`) + default: + enc.buf.AppendFloat(val, bitSize) + } +} + +// safeAddString JSON-escapes a string and appends it to the internal buffer. +// Unlike the standard library's encoder, it doesn't attempt to protect the +// user from browser vulnerabilities or JSONP-related problems. +func (enc *jsonWithContextEncoder) safeAddString(s string) { + safeAppendStringLike( + (*buffer.Buffer).AppendString, + utf8.DecodeRuneInString, + enc.buf, + s, + ) +} + +// safeAddByteString is no-alloc equivalent of safeAddString(string(s)) for s []byte. +func (enc *jsonWithContextEncoder) safeAddByteString(s []byte) { + safeAppendStringLike( + (*buffer.Buffer).AppendBytes, + utf8.DecodeRune, + enc.buf, + s, + ) +} + +// safeAppendStringLike is a generic implementation of safeAddString and safeAddByteString. +// It appends a string or byte slice to the buffer, escaping all special characters. +func safeAppendStringLike[S []byte | string]( + // appendTo appends this string-like object to the buffer. + appendTo func(*buffer.Buffer, S), + // decodeRune decodes the next rune from the string-like object + // and returns its value and width in bytes. + decodeRune func(S) (rune, int), + buf *buffer.Buffer, + s S, +) { + // The encoding logic below works by skipping over characters + // that can be safely copied as-is, + // until a character is found that needs special handling. + // At that point, we copy everything we've seen so far, + // and then handle that special character. + // + // last is the index of the last byte that was copied to the buffer. + last := 0 + for i := 0; i < len(s); { + if s[i] >= utf8.RuneSelf { + // Character >= RuneSelf may be part of a multi-byte rune. + // They need to be decoded before we can decide how to handle them. + r, size := decodeRune(s[i:]) + if r != utf8.RuneError || size != 1 { + // No special handling required. + // Skip over this rune and continue. + i += size + continue + } + + // Invalid UTF-8 sequence. + // Replace it with the Unicode replacement character. + appendTo(buf, s[last:i]) + buf.AppendString(`\ufffd`) + + i++ + last = i + } else { + // Character < RuneSelf is a single-byte UTF-8 rune. + if s[i] >= 0x20 && s[i] != '\\' && s[i] != '"' { + // No escaping necessary. + // Skip over this character and continue. + i++ + continue + } + + // This character needs to be escaped. + appendTo(buf, s[last:i]) + switch s[i] { + case '\\', '"': + buf.AppendByte('\\') + buf.AppendByte(s[i]) + case '\n': + buf.AppendByte('\\') + buf.AppendByte('n') + case '\r': + buf.AppendByte('\\') + buf.AppendByte('r') + case '\t': + buf.AppendByte('\\') + buf.AppendByte('t') + default: + // Encode bytes < 0x20, except for the escape sequences above. + buf.AppendString(`\u00`) + buf.AppendByte(_hex[s[i]>>4]) + buf.AppendByte(_hex[s[i]&0xF]) + } + + i++ + last = i + } + } + + // add remaining + appendTo(buf, s[last:]) +} diff --git a/core/logger/mg_transport_client_adapter.go b/core/logger/mg_transport_client_adapter.go index 917056f..345b5b3 100644 --- a/core/logger/mg_transport_client_adapter.go +++ b/core/logger/mg_transport_client_adapter.go @@ -2,18 +2,57 @@ package logger import ( "fmt" - v1 "github.com/retailcrm/mg-transport-api-client-go/v1" + "go.uber.org/zap" +) + +const ( + mgDebugLogReq = "MG TRANSPORT API Request: %s %s %s %v" + mgDebugLogReqFile = "MG TRANSPORT API Request: %s %s %s [file data]" + mgDebugLogResp = "MG TRANSPORT API Response: %s" ) type mgTransportClientAdapter struct { log Logger } -func MGTransportClientAdapter(log Logger) v1.DebugLogger { +// MGTransportClientAdapter constructs an adapter that will log MG requests and responses. +func MGTransportClientAdapter(log Logger) v1.BasicLogger { return &mgTransportClientAdapter{log: log} } +// Debugf writes a message with Debug level. func (m *mgTransportClientAdapter) Debugf(msg string, args ...interface{}) { - m.log.Debug(fmt.Sprintf(msg, args...)) + var body interface{} + switch msg { + case mgDebugLogReqFile: + body = "[file data]" + fallthrough + case mgDebugLogReq: + var method, uri, token string + if len(args) > 0 { + method = fmt.Sprint(args[0]) + } + if len(args) > 1 { + uri = fmt.Sprint(args[1]) + } + if len(args) > 2 { + token = fmt.Sprint(args[2]) + } + if len(args) > 3 { + body = args[3] + } + m.log.Debug("MG TRANSPORT API Request", + zap.String(HTTPMethodAttr, method), zap.String("url", uri), + zap.String("token", token), Body(body)) + case mgDebugLogResp: + m.log.Debug("MG TRANSPORT API Response", Body(args[0])) + default: + m.log.Debug(fmt.Sprintf(msg, args...)) + } +} + +// Printf is a v1.BasicLogger implementation. +func (m *mgTransportClientAdapter) Printf(msg string, args ...interface{}) { + m.Debugf(msg, args...) } diff --git a/core/logger/mg_transport_client_adapter_test.go b/core/logger/mg_transport_client_adapter_test.go new file mode 100644 index 0000000..262e389 --- /dev/null +++ b/core/logger/mg_transport_client_adapter_test.go @@ -0,0 +1,43 @@ +package logger + +import ( + "github.com/h2non/gock" + v1 "github.com/retailcrm/mg-transport-api-client-go/v1" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "net/http" + "testing" +) + +func TestMGTransportClientAdapter(t *testing.T) { + httpClient := &http.Client{} + log := newJSONBufferedLogger() + client := v1.NewWithClient("https://mg.dev", "test_token", httpClient). + WithLogger(MGTransportClientAdapter(log.Logger())) + client.Debug = true + + defer gock.Off() + gock.New("https://mg.dev"). + Get("/api/transport/v1/channels"). + Reply(http.StatusOK). + JSON([]v1.ChannelListItem{{ID: 123}}) + + _, _, err := client.TransportChannels(v1.Channels{}) + require.NoError(t, err) + + entries, err := log.ScanAll() + require.NoError(t, err) + require.Len(t, entries, 2) + + assert.Equal(t, "DEBUG", entries[0].LevelName) + assert.True(t, entries[0].DateTime.Valid) + assert.Equal(t, "MG TRANSPORT API Request", entries[0].Message) + assert.Equal(t, http.MethodGet, entries[0].Context["method"]) + assert.Equal(t, "test_token", entries[0].Context["token"]) + assert.Equal(t, "https://mg.dev/api/transport/v1/channels?", entries[0].Context["url"]) + + assert.Equal(t, "DEBUG", entries[1].LevelName) + assert.True(t, entries[1].DateTime.Valid) + assert.Equal(t, "MG TRANSPORT API Response", entries[1].Message) + assert.Equal(t, float64(123), entries[1].Context["body"].([]interface{})[0].(map[string]interface{})["id"]) +} diff --git a/core/logger/nil.go b/core/logger/nil.go index 282a13d..f6d0f95 100644 --- a/core/logger/nil.go +++ b/core/logger/nil.go @@ -5,8 +5,10 @@ import ( "go.uber.org/zap/zapcore" ) +// Nil logger doesn't do anything. type Nil struct{} +// NewNil constructs new *Nil. func NewNil() Logger { return &Nil{} } diff --git a/core/logger/pool.go b/core/logger/pool.go new file mode 100644 index 0000000..51695dc --- /dev/null +++ b/core/logger/pool.go @@ -0,0 +1,57 @@ +// Copyright (c) 2023 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package logger + +import ( + "sync" +) + +// A Pool is a generic wrapper around [sync.Pool] to provide strongly-typed +// object pooling. +// +// Note that SA6002 (ref: https://staticcheck.io/docs/checks/#SA6002) will +// not be detected, so all internal pool use must take care to only store +// pointer types. +type Pool[T any] struct { + pool sync.Pool +} + +// NewPool returns a new [Pool] for T, and will use fn to construct new Ts when +// the pool is empty. +func NewPool[T any](fn func() T) *Pool[T] { + return &Pool[T]{ + pool: sync.Pool{ + New: func() any { + return fn() + }, + }, + } +} + +// Get gets a T from the pool, or creates a new one if the pool is empty. +func (p *Pool[T]) Get() T { + return p.pool.Get().(T) +} + +// Put returns x into the pool. +func (p *Pool[T]) Put(x T) { + p.pool.Put(x) +} diff --git a/core/logger/writer_adapter.go b/core/logger/writer_adapter.go index e80459e..cceca9e 100644 --- a/core/logger/writer_adapter.go +++ b/core/logger/writer_adapter.go @@ -11,6 +11,7 @@ type writerAdapter struct { level zapcore.Level } +// WriterAdapter returns an io.Writer that can be used to write log messages. Message level is preconfigured. func WriterAdapter(log Logger, level zapcore.Level) io.Writer { return &writerAdapter{log: log, level: level} } diff --git a/core/logger/zabbix_collector_adapter.go b/core/logger/zabbix_collector_adapter.go index 0dc9067..e81345e 100644 --- a/core/logger/zabbix_collector_adapter.go +++ b/core/logger/zabbix_collector_adapter.go @@ -11,9 +11,24 @@ type zabbixCollectorAdapter struct { } func (a *zabbixCollectorAdapter) Errorf(format string, args ...interface{}) { - a.log.Error(fmt.Sprintf(format, args...)) + baseMsg := "cannot send metrics to Zabbix" + switch format { + case "cannot send metrics to Zabbix: %v": + baseMsg = "cannot stop collector" + fallthrough + case "cannot stop collector: %s": + var err interface{} + if len(args) > 0 { + err = args[0] + } + a.log.Error(baseMsg, Err(err)) + default: + a.log.Error(fmt.Sprintf(format, args...)) + } } +// ZabbixCollectorAdapter works as a logger adapter for Zabbix metrics collector. +// It can extract error messages from Zabbix collector and convert them to structured format. func ZabbixCollectorAdapter(log Logger) metrics.ErrorLogger { return &zabbixCollectorAdapter{log: log} } diff --git a/core/logger/zap.go b/core/logger/zap.go index 53d598b..1b8730b 100644 --- a/core/logger/zap.go +++ b/core/logger/zap.go @@ -71,7 +71,7 @@ func NewZapJSON(debug bool) *zap.Logger { log, err := zap.Config{ Level: zap.NewAtomicLevelAt(level), Development: debug, - Encoding: "json", + Encoding: "json-with-context", EncoderConfig: EncoderConfigJSON(), OutputPaths: []string{"stdout"}, ErrorOutputPaths: []string{"stderr"}, diff --git a/core/util/httputil/http_client_builder_test.go b/core/util/httputil/http_client_builder_test.go index 36d5931..862783a 100644 --- a/core/util/httputil/http_client_builder_test.go +++ b/core/util/httputil/http_client_builder_test.go @@ -142,7 +142,7 @@ func (t *HTTPClientBuilderTest) Test_WithLogger() { builder.WithLogger(nil) assert.Nil(t.T(), builder.logger) - log := logger.NewDefault("console", true) + log := logger.NewDefault("json", true) builder.WithLogger(log) assert.NotNil(t.T(), builder.logger) } diff --git a/core/util/testutil/buffer_logger.go b/core/util/testutil/buffer_logger.go index ff8ddf8..9df5871 100644 --- a/core/util/testutil/buffer_logger.go +++ b/core/util/testutil/buffer_logger.go @@ -36,8 +36,8 @@ func NewBufferedLogger() BufferedLogger { bl := &BufferLogger{} bl.Logger = zap.New( zapcore.NewCore( - zapcore.NewConsoleEncoder( - logger.EncoderConfigConsole()), zap.CombineWriteSyncers(os.Stdout, os.Stderr, &bl.buf), zapcore.DebugLevel)) + logger.NewJSONWithContextEncoder( + logger.EncoderConfigJSON()), zap.CombineWriteSyncers(os.Stdout, os.Stderr, &bl.buf), zapcore.DebugLevel)) return bl } diff --git a/core/util/testutil/buffer_logger_test.go b/core/util/testutil/buffer_logger_test.go index f144082..8d0771d 100644 --- a/core/util/testutil/buffer_logger_test.go +++ b/core/util/testutil/buffer_logger_test.go @@ -29,17 +29,20 @@ func (t *BufferLoggerTest) Test_Read() { data, err := io.ReadAll(t.logger) t.Require().NoError(err) - t.Assert().Contains(string(data), "level=DEBUG test") + t.Assert().Contains(string(data), "\"level_name\":\"DEBUG\"") + t.Assert().Contains(string(data), "\"message\":\"test\"") } func (t *BufferLoggerTest) Test_Bytes() { t.logger.Debug("test") - t.Assert().Contains(string(t.logger.Bytes()), "level=DEBUG test") + t.Assert().Contains(string(t.logger.Bytes()), "\"level_name\":\"DEBUG\"") + t.Assert().Contains(string(t.logger.Bytes()), "\"message\":\"test\"") } func (t *BufferLoggerTest) Test_String() { t.logger.Debug("test") - t.Assert().Contains(t.logger.String(), "level=DEBUG test") + t.Assert().Contains(t.logger.String(), "\"level_name\":\"DEBUG\"") + t.Assert().Contains(t.logger.String(), "\"message\":\"test\"") } func (t *BufferLoggerTest) TestRace() { diff --git a/core/util/testutil/json_record_scanner.go b/core/util/testutil/json_record_scanner.go new file mode 100644 index 0000000..2a422c1 --- /dev/null +++ b/core/util/testutil/json_record_scanner.go @@ -0,0 +1,51 @@ +package testutil + +import ( + "bufio" + "encoding/json" + "github.com/guregu/null/v5" + "io" +) + +type LogRecord struct { + LevelName string `json:"level_name"` + DateTime null.Time `json:"datetime"` + Caller string `json:"caller"` + Message string `json:"message"` + Handler string `json:"handler,omitempty"` + Connection string `json:"connection,omitempty"` + Account string `json:"account,omitempty"` + Context map[string]interface{} `json:"context,omitempty"` +} + +type JSONRecordScanner struct { + r *bufio.Scanner + e LogRecord +} + +func NewJSONRecordScanner(entryProvider io.Reader) *JSONRecordScanner { + return &JSONRecordScanner{r: bufio.NewScanner(entryProvider)} +} + +func (s *JSONRecordScanner) Scan() error { + if s.r.Scan() { + return json.Unmarshal(s.r.Bytes(), &s.e) + } + return io.EOF +} + +func (s *JSONRecordScanner) ScanAll() ([]LogRecord, error) { + var entries []LogRecord + for s.r.Scan() { + entry := LogRecord{} + if err := json.Unmarshal(s.r.Bytes(), &entry); err != nil { + return entries, err + } + entries = append(entries, entry) + } + return entries, nil +} + +func (s *JSONRecordScanner) Entry() LogRecord { + return s.e +} diff --git a/core/util/testutil/json_record_scanner_test.go b/core/util/testutil/json_record_scanner_test.go new file mode 100644 index 0000000..4cf4fea --- /dev/null +++ b/core/util/testutil/json_record_scanner_test.go @@ -0,0 +1,107 @@ +package testutil + +import ( + "bytes" + "github.com/stretchr/testify/suite" + "io" + "strings" + "testing" + "time" +) + +type JSONRecordScannerTest struct { + suite.Suite +} + +func TestJSONRecordScanner(t *testing.T) { + suite.Run(t, new(JSONRecordScannerTest)) +} + +func (t *JSONRecordScannerTest) new(lines []string) *JSONRecordScanner { + return NewJSONRecordScanner(bytes.NewReader([]byte(strings.Join(lines, "\n")))) +} + +func (t *JSONRecordScannerTest) newPredefined() *JSONRecordScanner { + return t.new([]string{strings.ReplaceAll(`{ + "level_name": "ERROR", + "datetime": "2024-06-07T13:49:17+03:00", + "caller": "handlers/account_middleware.go:147", + "message": "Cannot add account", + "handler": "handlers.addAccount", + "connection": "https://fake-uri.retailcrm.pro", + "account": "@username", + "context": { + "body": "[]string{\"integration_read\", \"integration_write\"}", + "statusCode": 500 + } +}`, "\n", "")}) +} + +func (t *JSONRecordScannerTest) assertPredefined(record LogRecord) { + ts, err := time.Parse(time.RFC3339, "2024-06-07T13:49:17+03:00") + t.Require().NoError(err) + t.Assert().True(record.DateTime.Valid) + t.Assert().Equal(ts, record.DateTime.Time) + t.Assert().Equal("ERROR", record.LevelName) + t.Assert().Equal("handlers/account_middleware.go:147", record.Caller) + t.Assert().Equal("Cannot add account", record.Message) + t.Assert().Equal("handlers.addAccount", record.Handler) + t.Assert().Equal("https://fake-uri.retailcrm.pro", record.Connection) + t.Assert().Equal("@username", record.Account) + t.Assert().Equal("[]string{\"integration_read\", \"integration_write\"}", record.Context["body"]) + t.Assert().Equal(float64(500), record.Context["statusCode"]) +} + +func (t *JSONRecordScannerTest) TestScan_NotJSON() { + rs := t.new([]string{"this is", "not json"}) + t.Assert().Error(rs.Scan()) +} + +func (t *JSONRecordScannerTest) TestScan_PartialJSON() { + rs := t.new([]string{"{}", "not json"}) + t.Assert().NoError(rs.Scan()) + t.Assert().Error(rs.Scan()) +} + +func (t *JSONRecordScannerTest) TestScan_JSON() { + rs := t.new([]string{"{}", "{}"}) + t.Assert().NoError(rs.Scan()) + t.Assert().NoError(rs.Scan()) + t.Assert().ErrorIs(rs.Scan(), io.EOF) +} + +func (t *JSONRecordScannerTest) TestScan_JSONRecord() { + rs := t.newPredefined() + t.Assert().NoError(rs.Scan()) + t.Assert().ErrorIs(rs.Scan(), io.EOF) + t.assertPredefined(rs.Entry()) +} + +func (t *JSONRecordScannerTest) TestScanAll_NotJSON() { + rs := t.new([]string{"this is", "not json"}) + records, err := rs.ScanAll() + t.Assert().Error(err) + t.Assert().Empty(records) +} + +func (t *JSONRecordScannerTest) TestScanAll_PartialJSON() { + rs := t.new([]string{"{}", "not json"}) + records, err := rs.ScanAll() + t.Assert().Error(err) + t.Assert().Len(records, 1) +} + +func (t *JSONRecordScannerTest) TestScanAll_JSON() { + rs := t.new([]string{"{}", "{}"}) + records, err := rs.ScanAll() + t.Assert().NoError(err) + t.Assert().Len(records, 2) +} + +func (t *JSONRecordScannerTest) TestScanAll_JSONRecord() { + rs := t.newPredefined() + records, err := rs.ScanAll() + t.Assert().NoError(err) + t.Assert().Len(records, 1) + t.assertPredefined(records[0]) +} diff --git a/core/util/utils_test.go b/core/util/utils_test.go index c1d577c..5372b52 100644 --- a/core/util/utils_test.go +++ b/core/util/utils_test.go @@ -38,7 +38,7 @@ func mgClient() *v1.MgClient { } func (u *UtilsTest) SetupSuite() { - logger := logger.NewDefault("console", true) + logger := logger.NewDefault("json", true) awsConfig := config.AWS{ AccessKeyID: "access key id (will be removed)", SecretAccessKey: "secret access key", diff --git a/go.mod b/go.mod index b458d9d..ea7bd71 100644 --- a/go.mod +++ b/go.mod @@ -1,6 +1,8 @@ module github.com/retailcrm/mg-transport-core/v2 -go 1.21 +go 1.21.4 + +toolchain go1.22.0 require ( github.com/DATA-DOG/go-sqlmock v1.3.3 @@ -17,6 +19,7 @@ require ( github.com/gomarkdown/markdown v0.0.0-20221013030248-663e2500819c github.com/gorilla/securecookie v1.1.1 github.com/gorilla/sessions v1.2.0 + github.com/guregu/null/v5 v5.0.0 github.com/h2non/gock v1.2.0 github.com/jessevdk/go-flags v1.4.0 github.com/jinzhu/gorm v1.9.11 diff --git a/go.sum b/go.sum index 3c610f9..5cf0ba1 100644 --- a/go.sum +++ b/go.sum @@ -238,6 +238,8 @@ github.com/gorilla/securecookie v1.1.1/go.mod h1:ra0sb63/xPlUeL+yeDciTfxMRAA+MP+ github.com/gorilla/sessions v1.2.0 h1:S7P+1Hm5V/AT9cjEcUD5uDaQSX0OE577aCXgoaKpYbQ= github.com/gorilla/sessions v1.2.0/go.mod h1:dk2InVEVJ0sfLlnXv9EAgkf6ecYs/i80K/zI+bUmuGM= github.com/gorilla/websocket v1.4.1/go.mod h1:YR8l580nyteQvAITg2hZ9XVh4b55+EU/adAjf1fMHhE= +github.com/guregu/null/v5 v5.0.0 h1:PRxjqyOekS11W+w/7Vfz6jgJE/BCwELWtgvOJzddimw= +github.com/guregu/null/v5 v5.0.0/go.mod h1:SjupzNy+sCPtwQTKWhUCqjhVCO69hpsl2QsZrWHjlwU= github.com/h2non/gock v1.2.0 h1:K6ol8rfrRkUOefooBC8elXoaNGYkpp7y2qcxGG6BzUE= github.com/h2non/gock v1.2.0/go.mod h1:tNhoxHYW2W42cYkYb1WqzdbYIieALC99kpYr7rH/BQk= github.com/h2non/parth v0.0.0-20190131123155-b4df798d6542 h1:2VTzZjLZBgl62/EtslCrtky5vbi9dd7HrQPQIx6wqiw=