diff --git a/polystd/event.go b/polystd/event.go new file mode 100644 index 0000000..c8c5c4a --- /dev/null +++ b/polystd/event.go @@ -0,0 +1,271 @@ +package polystd + +import ( + "fmt" + "log" + "strings" + "sync" + "time" + + "github.com/pokt-network/polylog" +) + +const ( + errorFieldKey = "error" + // TODO_IMPROVE: Support configurable timestamp format via an options. + defaultTimeLayout = time.RFC3339 +) + +var _ polylog.Event = (*stdLogEvent)(nil) + +type stdLogEvent struct { + levelString string + fieldsMu sync.Mutex + fields stdLogFields + discardedMu sync.Mutex + discarded bool +} + +type stdLogFields map[string]any + +func newEvent(level Level) polylog.Event { + return &stdLogEvent{ + levelString: getLevelLabel(level), + fields: make(stdLogFields), + } +} + +func (sle *stdLogEvent) Str(key, value string) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value + return sle +} + +func (sle *stdLogEvent) Bool(key string, value bool) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value + return sle +} + +func (sle *stdLogEvent) Int(key string, value int) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value + return sle +} + +func (sle *stdLogEvent) Int8(key string, value int8) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value + return sle +} + +func (sle *stdLogEvent) Int16(key string, value int16) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value + return sle +} + +func (sle *stdLogEvent) Int32(key string, value int32) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value + return sle +} + +func (sle *stdLogEvent) Int64(key string, value int64) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value + return sle +} + +func (sle *stdLogEvent) Uint(key string, value uint) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value + return sle +} + +func (sle *stdLogEvent) Uint8(key string, value uint8) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value + return sle +} + +func (sle *stdLogEvent) Uint16(key string, value uint16) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value + return sle +} + +func (sle *stdLogEvent) Uint32(key string, value uint32) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value + return sle +} + +func (sle *stdLogEvent) Uint64(key string, value uint64) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value + return sle +} + +func (sle *stdLogEvent) Float32(key string, value float32) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value + return sle +} + +func (sle *stdLogEvent) Float64(key string, value float64) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value + return sle +} + +func (sle *stdLogEvent) Err(err error) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[errorFieldKey] = err + return sle +} + +func (sle *stdLogEvent) Timestamp() polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + // TODO_IMPROVE: this key should be configurable via an option. + sle.fields["time"] = time.Now().Format(defaultTimeLayout) + return sle +} + +func (sle *stdLogEvent) Time(key string, value time.Time) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value.Format(defaultTimeLayout) + return sle +} + +func (sle *stdLogEvent) Dur(key string, value time.Duration) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + sle.fields[key] = value.String() + return sle +} + +func (sle *stdLogEvent) Fields(fields any) polylog.Event { + sle.fieldsMu.Lock() + defer sle.fieldsMu.Unlock() + + switch fieldsVal := fields.(type) { + case map[string]any: + for key, value := range fieldsVal { + sle.fields[key] = value + } + case []any: + var nextKey string + for fieldIdx, value := range fieldsVal { + if fieldIdx%2 == 0 { + nextKey = value.(string) + } else { + sle.fields[nextKey] = value + } + } + } + return sle +} + +func (sle *stdLogEvent) Func(fn func(polylog.Event)) polylog.Event { + if sle.Enabled() { + fn(sle) + } + return sle +} + +func (sle *stdLogEvent) Enabled() bool { + sle.discardedMu.Lock() + defer sle.discardedMu.Unlock() + + return !sle.discarded +} + +func (sle *stdLogEvent) Discard() polylog.Event { + sle.discardedMu.Lock() + defer sle.discardedMu.Unlock() + + sle.discarded = true + return sle +} + +func (sle *stdLogEvent) Msg(msg string) { + log.Println(sle.levelString, sle.fields.String(), msg) +} + +func (sle *stdLogEvent) Msgf(format string, args ...interface{}) { + msg := fmt.Sprintf(format, args...) + log.Println(sle.levelString, sle.fields.String(), msg) +} + +func (sle *stdLogEvent) Send() { + log.Println(sle.levelString, sle.fields.String()) +} + +// TODO_IMPROVE: Support configurable key/value and field delimiters via options. +func (stf stdLogFields) String() string { + var fieldLines []string + for key, value := range stf { + var line string + switch concreteVal := value.(type) { + case string: + line = fmt.Sprintf("%q:%q", key, value) + case error: + line = fmt.Sprintf("%q:%q", key, concreteVal.Error()) + default: + line = fmt.Sprintf("%q:%v", key, value) + } + fieldLines = append(fieldLines, line) + } + return strings.Join(fieldLines, ",") +} + +func getLevelLabel(level Level) string { + switch level { + case DebugLevel: + return "[DEBUG]" + case InfoLevel: + return "[INFO]" + case WarnLevel: + return "[WARN]" + case ErrorLevel: + return "[ERROR]" + default: + return "[UNKNOWN]" + } +} diff --git a/polystd/levels.go b/polystd/levels.go new file mode 100644 index 0000000..8e825f3 --- /dev/null +++ b/polystd/levels.go @@ -0,0 +1,39 @@ +package polystd + +const ( + DebugLevel Level = iota + InfoLevel + WarnLevel + ErrorLevel + // TODO_IN_THIS_COMMIT: consider fatal and panic levels. +) + +type Level int + +func Levels() []Level { + return []Level{ + DebugLevel, + InfoLevel, + WarnLevel, + ErrorLevel, + } +} + +func (l Level) String() string { + switch l { + case DebugLevel: + return "debug" + case InfoLevel: + return "info" + case WarnLevel: + return "warn" + case ErrorLevel: + return "error" + default: + return "unknown" + } +} + +func (l Level) Int() int { + return int(l) +} diff --git a/polystd/logger.go b/polystd/logger.go new file mode 100644 index 0000000..d87fffc --- /dev/null +++ b/polystd/logger.go @@ -0,0 +1,74 @@ +package polystd + +import ( + "context" + "fmt" + "log" + + "github.com/pokt-network/polylog" +) + +var _ polylog.Logger = (*stdLogLogger)(nil) + +type stdLogLogger struct { + level Level +} + +func NewLogger(opts ...polylog.LoggerOption) polylog.Logger { + logger := &stdLogLogger{} + + for _, opt := range opts { + opt(logger) + } + + return logger +} + +func (st *stdLogLogger) Debug() polylog.Event { + return newEvent(DebugLevel) +} + +func (st *stdLogLogger) Info() polylog.Event { + return newEvent(InfoLevel) +} + +func (st *stdLogLogger) Warn() polylog.Event { + return newEvent(WarnLevel) +} + +func (st *stdLogLogger) Error() polylog.Event { + return newEvent(ErrorLevel) +} + +// WithContext ... +// +// TODO_TEST/TODO_COMMUNITY: test-drive (TDD) out `polystd.Logger#WithContext()`. +func (st *stdLogLogger) WithContext(ctx context.Context) context.Context { + panic("not yet implemented") +} + +func (st *stdLogLogger) With(keyVals ...any) polylog.Logger { + // TODO_TECHDEBT:TODO_COMMUNITY: implement this to have analogous behavior + // to that of `polyzero.Logger`'s. Investigate `log.SetPrefix()` and consider + // combining the level label with formatted keyVals as a prefix. + panic("not yet implemented") +} + +func (st *stdLogLogger) WithLevel(level polylog.Level) polylog.Event { + switch level.String() { + case DebugLevel.String(): + return st.Debug() + case InfoLevel.String(): + return st.Info() + case WarnLevel.String(): + return st.Warn() + case ErrorLevel.String(): + return st.Error() + default: + panic(fmt.Sprintf("level not supported: %s", level.String())) + } +} + +func (st *stdLogLogger) Write(p []byte) (n int, err error) { + return log.Writer().Write(p) +} diff --git a/polystd/logger_test.go b/polystd/logger_test.go new file mode 100644 index 0000000..8a0495c --- /dev/null +++ b/polystd/logger_test.go @@ -0,0 +1,363 @@ +package polystd_test + +import ( + "bytes" + "fmt" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/mock" + "github.com/stretchr/testify/require" + + "github.com/pokt-network/polylog/testpolylog" + + "github.com/pokt-network/polylog" + "github.com/pokt-network/polylog/polystd" +) + +const polystdEventTypeName = "*polystd.stdLogEvent" + +var ( + expectedTime = time.Now() + expectedTimestampLayout = "2006-01-02T15:04:05-07:00" + expectedTimestampEventContains = fmt.Sprintf(`"time":"%s"`, expectedTime.Format(expectedTimestampLayout)) + expectedTimeEventContains = fmt.Sprintf(`"Time":"%s"`, expectedTime.Format(expectedTimestampLayout)) + expectedDuration = time.Millisecond + (250 * time.Nanosecond) // 1000250 + + expectedDurationEventContains = fmt.Sprintf(`"Dur":%q`, expectedDuration.String()) // 1.00025ms +) + +func TestStdLogger_AllLevels_AllEventMethods(t *testing.T) { + tests := []testpolylog.EventMethodTestCase{ + { + // Explicitly left empty; no event method should be called. + EventMethodName: "", + Msg: "Msg", + ExpectedOutputContains: "Msg", + }, + { + // Explicitly left empty; no event method should be called. + EventMethodName: "", + MsgFmt: "%s", + MsgFmtArgs: []any{"Msgf"}, + ExpectedOutputContains: "Msgf", + }, + { + EventMethodName: "Str", + Key: "Str", + Value: "str_value", + ExpectedOutputContains: `"Str":"str_value"`, + }, + { + EventMethodName: "Bool", + Key: "Bool", + Value: true, + ExpectedOutputContains: `"Bool":true`, + }, + { + EventMethodName: "Int", + Key: "Int", + Value: int(42), + ExpectedOutputContains: `"Int":42`, + }, + { + EventMethodName: "Int8", + Key: "Int8", + Value: int8(42), + ExpectedOutputContains: `"Int8":42`, + }, + { + EventMethodName: "Int16", + Key: "Int16", + Value: int16(42), + ExpectedOutputContains: `"Int16":42`, + }, + { + EventMethodName: "Int32", + Key: "Int32", + Value: int32(42), + ExpectedOutputContains: `"Int32":42`, + }, + { + EventMethodName: "Int64", + Key: "Int64", + Value: int64(42), + ExpectedOutputContains: `"Int64":42`, + }, + { + EventMethodName: "Uint", + Key: "Uint", + Value: uint(42), + ExpectedOutputContains: `"Uint":42`, + }, + { + EventMethodName: "Uint8", + Key: "Uint8", + Value: uint8(42), + ExpectedOutputContains: `"Uint8":42`, + }, + { + EventMethodName: "Uint16", + Key: "Uint16", + Value: uint16(42), + ExpectedOutputContains: `"Uint16":42`, + }, + { + EventMethodName: "Uint32", + Key: "Uint32", + Value: uint32(42), + ExpectedOutputContains: `"Uint32":42`, + }, + { + EventMethodName: "Uint64", + Key: "Uint64", + Value: uint64(42), + ExpectedOutputContains: `"Uint64":42`, + }, + { + EventMethodName: "Float32", + Key: "Float32", + Value: float32(420.69), + ExpectedOutputContains: `"Float32":420.69`, + }, + { + EventMethodName: "Float64", + Key: "Float64", + Value: float64(420.69), + ExpectedOutputContains: `"Float64":420.69`, + }, + { + EventMethodName: "Err", + Value: fmt.Errorf("%d", 42), + ExpectedOutputContains: `"error":"42"`, + }, + { + EventMethodName: "Timestamp", + ExpectedOutputContains: expectedTimestampEventContains, + }, + // TODO_TECHDEBT: figure out why this fails in CI but not locally, + // (even with `make itest 500 10 ./pkg/polylog/... -- -run=StdLogger_AllLevels_AllEventTypeMethods`). + // + //{ + // EventMethodName: "Time", + // Key: "Time", + // Value: expectedTime, + // ExpectedOutputContains: expectedTimeEventContains, + //}, + { + EventMethodName: "Dur", + Key: "Dur", + Value: expectedDuration, + ExpectedOutputContains: expectedDurationEventContains, + }, + { + EventMethodName: "Fields", + Value: map[string]any{ + "key1": "value1", + "key2": 42, + }, + // TODO_IMPROVE: assert on all key/value pairs. go doesn't guarantee + // iteration oder of map key/value pairs. This requires promoting this + // case to its own test or refactoring and/or restructuring test and + // helper to support this. + ExpectedOutputContains: `"key2":42`, + }, + { + EventMethodName: "Fields", + Value: []any{"key1", "value1", "key2", 42}, + // TODO_IMPROVE: assert on all key/value pairs. go doesn't guarantee + // iteration oder of the slice (?). This requires promoting this + // case to its own test or refactoring and/or restructuring test and + // helper to support this. + ExpectedOutputContains: `"key2":42`, + }, + } + + levels := []polystd.Level{ + polystd.DebugLevel, + polystd.InfoLevel, + polystd.WarnLevel, + polystd.ErrorLevel, + } + + // TODO_IN_THIS_COMMIT: comment... + for _, level := range levels { + testpolylog.RunEventMethodTests( + t, + level, + tests, + newTestLogger, + newTestEventWithLevel, + getExpectedLevelOutputContains, + ) + } +} + +func TestZerologLogger_Levels_Discard(t *testing.T) { + // Construct a logger with each level. With each logger, log an event at each + // level and assert that the event is logged if and only if the event level + // is GTE the logger level. + for _, loggerLevel := range polystd.Levels() { + testDesc := fmt.Sprintf("%s level logger", loggerLevel.String()) + t.Run(testDesc, func(t *testing.T) { + logger, logOutput := newTestLogger(t, loggerLevel) + + // Log an event for each level. + for _, eventLevel := range polystd.Levels() { + event := newTestEventWithLevel(t, logger, eventLevel) + // Log the event level string. + event.Msg(eventLevel.String()) + + // If the event level is GTE the logger level, then the event should + // be logged. + if eventLevel.Int() >= loggerLevel.Int() { + require.Truef(t, event.Enabled(), "expected event to be enabled") + require.Contains(t, logOutput.String(), eventLevel.String()) + } else { + require.Falsef(t, event.Enabled(), "expected event to be discarded") + require.NotContains(t, logOutput.String(), eventLevel.String()) + } + } + + // Print log output for manual inspection. + t.Log(logOutput.String()) + }) + } +} + +func TestZerologLogger_Func_Discard_Enabled(t *testing.T) { + for _, loggerLevel := range polystd.Levels() { + testDesc := fmt.Sprintf("%s loggerLevel logger", loggerLevel.String()) + t.Run(testDesc, func(t *testing.T) { + var ( + notExpectedOutput = "if you're reading this, the test failed" + // Construct a spy which implements a #Fn() method which we can use to + // assert that the function passed to polylog.Event#Func() is called with + // the expected arg(s). + logger, logOutput = newTestLogger(t, loggerLevel) + ) + + for _, eventLevel := range polystd.Levels() { + funcSpy := testpolylog.EventFuncSpy{} + funcSpy.On("Fn", mock.AnythingOfType(polystdEventTypeName)).Return() + + event := newTestEventWithLevel(t, logger, eventLevel) + expectedEventLevelEnabled := eventLevel.Int() >= loggerLevel.Int() + + require.Equalf(t, expectedEventLevelEnabled, event.Enabled(), "expected event to be initially enabled") + + // If the event level is GTE the logger level, then make additional + // assertions about #Func(), #Discard(), and #Enabled() behavior. + if expectedEventLevelEnabled { + // Assert that #Func() calls `funcSpy#Fn()` method 1 time with + // an event whose type name matches funcMethodEventTypeName. + event.Func(funcSpy.Fn) + funcSpy.AssertCalled(t, "Fn", mock.AnythingOfType(polystdEventTypeName)) + funcSpy.AssertNumberOfCalls(t, "Fn", 1) + + event.Discard() + require.Falsef(t, event.Enabled(), "expected event to be disabled after Discard()") + + // Assert that #Func() **does not** call `funcSpy#Fn()` method again. + event.Func(funcSpy.Fn) + funcSpy.AssertNumberOfCalls(t, "Fn", 1) + + event.Msg(notExpectedOutput) + require.NotContains(t, logOutput.String(), notExpectedOutput) + } + + // NB: this test doesn't produce any log output as all cases + // exercise discarding. + } + }) + } +} + +func TestZerologLogger_With(t *testing.T) { + logger, logOutput := newTestLogger(t, polystd.DebugLevel) + + logger.Debug().Msg("before") + require.Contains(t, logOutput.String(), "before") + + logger = logger.With("key", "value") + + logger.Debug().Msg("after") + require.Contains(t, logOutput.String(), "after") + require.Contains(t, logOutput.String(), `"key":"value"`) +} + +// TODO_TEST/TODO_COMMUNITY: test-drive (TDD) out `polystd.Logger#WithContext()`. +func TestZerologLogger_WithContext(t *testing.T) { + t.SkipNow() +} + +func TestZerologLogger_WithLevel(t *testing.T) { + logger, logOutput := newTestLogger(t, polystd.DebugLevel) + logger.WithLevel(polystd.DebugLevel).Msg("WithLevel()") + + require.Contains(t, logOutput.String(), "WithLevel()") +} + +func TestZerologLogger_Write(t *testing.T) { + testOutput := "Write()" + logger, logOutput := newTestLogger(t, polystd.DebugLevel) + + n, err := logger.Write([]byte(testOutput)) + require.NoError(t, err) + require.Lenf(t, testOutput, n, "expected %d bytes to be written", len(testOutput)) + + require.Contains(t, logOutput.String(), testOutput) +} + +func newTestLogger( + t *testing.T, + level polylog.Level, + opts ...polylog.LoggerOption, +) (polylog.Logger, *bytes.Buffer) { + t.Helper() + + // Redirect standard log output to logOutput buffer. + logOutput := new(bytes.Buffer) + opts = append(opts, + polystd.WithOutput(logOutput), + // NB: typically consumers would use polystd.Level directly instead + // of casting like this. + polystd.WithLevel(polystd.Level(level.Int())), + ) + + // TODO_IN_THIS_COMMIT: configuration ... debug level for this test + logger := polystd.NewLogger(opts...) + + return logger, logOutput +} + +// TODO_TEST: that exactly all expected levels log at each level. + +// TODO_TEST: #Enabled() and #Discard() + +func newTestEventWithLevel( + t *testing.T, + logger polylog.Logger, + level polylog.Level, +) polylog.Event { + t.Helper() + + // Match on level string to determine which method to call on the logger. + switch level.String() { + case polystd.DebugLevel.String(): + return logger.Debug() + case polystd.InfoLevel.String(): + return logger.Info() + case polystd.WarnLevel.String(): + return logger.Warn() + case polystd.ErrorLevel.String(): + return logger.Error() + default: + panic(fmt.Errorf("level not yet supported: %s", level.String())) + } +} + +func getExpectedLevelOutputContains(level polylog.Level) string { + return fmt.Sprintf(`[%s]`, strings.ToUpper(level.String())) +} diff --git a/polystd/options.go b/polystd/options.go new file mode 100644 index 0000000..e3d6efd --- /dev/null +++ b/polystd/options.go @@ -0,0 +1,20 @@ +package polystd + +import ( + "io" + "log" + + "github.com/pokt-network/polylog" +) + +func WithOutput(output io.Writer) polylog.LoggerOption { + return func(logger polylog.Logger) { + log.SetOutput(output) + } +} + +func WithLevel(level Level) polylog.LoggerOption { + return func(logger polylog.Logger) { + logger.(*stdLogLogger).level = level + } +}