From aeb27650dba14b35f0dd5ab4798db46db1f8d35e Mon Sep 17 00:00:00 2001 From: Gerard Vanloo Date: Mon, 11 Apr 2022 17:54:28 -0400 Subject: [PATCH] Reorganizing and cleaning up files; Fixing tests in log directory --- .../sink/fake_encoder_test.go | 0 internal/sink/observerable_test.go | 164 ++++++ internal/sink/sink.go | 16 + internal/sink/sink_test.go | 538 ++++++++++++++++++ log/fakes_test.go | 28 - log/log.go | 20 +- log/log_test.go | 180 +----- log/logsink_test.go | 380 ------------- log/observer_test.go | 164 ------ log/options.go | 4 +- 10 files changed, 754 insertions(+), 740 deletions(-) rename log/fake_test.go => internal/sink/fake_encoder_test.go (100%) create mode 100644 internal/sink/observerable_test.go create mode 100644 internal/sink/sink_test.go delete mode 100644 log/fakes_test.go delete mode 100644 log/logsink_test.go delete mode 100644 log/observer_test.go diff --git a/log/fake_test.go b/internal/sink/fake_encoder_test.go similarity index 100% rename from log/fake_test.go rename to internal/sink/fake_encoder_test.go diff --git a/internal/sink/observerable_test.go b/internal/sink/observerable_test.go new file mode 100644 index 0000000..50f56bc --- /dev/null +++ b/internal/sink/observerable_test.go @@ -0,0 +1,164 @@ +package sink_test +// +// import ( +// "bytes" +// "encoding/json" +// "fmt" +// "io" +// "io/ioutil" +// "os" +// "strconv" +// "testing" +// "time" +// +// "github.com/ViaQ/logerr/v2/kverrors" +// "github.com/ViaQ/logerr/v2/internal/sink" +// "github.com/ViaQ/logerr/v2/log" +// "github.com/go-logr/logr" +// "github.com/stretchr/testify/require" +// ) +// +// type Fields map[string]interface{} +// +// // assertLoggedFields checks that all of fields exists in the entry. +// func assertLoggedFields(t *testing.T, entry *observableEntry, fields Fields) { +// var f []string +// for k := range fields { +// f = append(f, k) +// } +// +// ctx := entry.Fields(f...) +// +// for k, v := range fields { +// value, ok := ctx[k] +// require.True(t, ok, "expected key '%s:%v' to exist in logged entry %+v", k, v, entry) +// actual, e := json.Marshal(value) +// require.NoError(t, e) +// expected, e := json.Marshal(v) +// require.NoError(t, e) +// require.JSONEq(t, string(expected), string(actual), "key: %q", k) +// } +// } +// +// type observableEntry struct { +// Component string +// Message string +// Timestamp string +// Context map[string]interface{} +// Error error +// Verbosity sink.Verbosity +// FileLine string +// } +// +// // Fields filters the entry to the specified fields and returns the result as a map. +// // This will include all known/parsed fields (such as Message, Timestamp) as well as +// // all Context items. +// func (o *observableEntry) Fields(fields ...string) Fields { +// entry := o.ToMap() +// filtered := Fields{} +// +// for _, f := range fields { +// filtered[f] = entry[f] +// } +// return filtered +// } +// +// // RawFields drops all but the specified from the entry and returns the encoded result +// func (o *observableEntry) RawFields(fields ...string) ([]byte, error) { +// filtered := o.Fields(fields...) +// b := bytes.NewBuffer(nil) +// err := log.JSONEncoder{}.Encode(b, filtered) +// return b.Bytes(), err +// } +// +// func (o *observableEntry) ToMap() map[string]interface{} { +// m := make(map[string]interface{}, len(o.Context)) +// for k, v := range o.Context { +// m[k] = v +// } +// m[log.ErrorKey] = o.Error +// m[log.MessageKey] = o.Message +// m[log.TimeStampKey] = o.Timestamp +// m[log.ComponentKey] = o.Component +// m[log.LevelKey] = o.Verbosity +// m[log.FileLineKey] = o.FileLine +// return m +// } +// +// func (o *observableEntry) Raw() ([]byte, error) { +// entry := o.ToMap() +// +// b := bytes.NewBuffer(nil) +// err := log.JSONEncoder{}.Encode(b, entry) +// return b.Bytes(), err +// } +// +// // observableEncoder stores all entries in a buffer rather than encoding them to an output +// type observableEncoder struct { +// entries []*observableEntry +// } +// +// // Encode stores all entries in a buffer rather than encoding them to an output +// func (o *observableEncoder) Encode(_ io.Writer, m interface{}) error { +// o.entries = append(o.entries, parseEntry(m)) +// return nil +// } +// +// // Logs returns all logs in the buffer +// func (o *observableEncoder) Logs() []*observableEntry { +// return o.entries +// } +// +// // TakeAll returns all logs and clears the buffer +// func (o *observableEncoder) TakeAll() []*observableEntry { +// defer o.Reset() +// return o.Logs() +// } +// +// // Reset empties the buffer +// func (o *observableEncoder) Reset() { +// o.entries = make([]*observableEntry, 0) +// } +// +// // parseEntry parses all known fields into the observableEntry struct and places +// // everything else in the Context field +// func parseEntry(entry interface{}) *observableEntry { +// // Make a copy, don't alter the argument as a side effect. +// m := entry.(log.Line) +// verbosity, err := strconv.Atoi(m.Verbosity) +// if err != nil { +// log.NewLogger("").Error(err, "failed to parse string as verbosity") +// } +// +// var resultErr error = nil +// if errVal, ok := m.Context[log.ErrorKey]; ok { +// if resultErr, ok = errVal.(error); !ok { +// fmt.Fprintf(os.Stderr, "failed to parse error from message: %v\n", kverrors.New("malformed/missing key", "key", log.ErrorKey)) +// } +// } +// delete(m.Context, log.ErrorKey) +// +// result := &observableEntry{ +// Timestamp: m.Timestamp, +// FileLine: m.FileLine, +// Verbosity: log.Verbosity(verbosity), +// Component: m.Component, +// Message: m.Message, +// Context: m.Context, +// Error: resultErr, +// } +// +// return result +// } +// +// // NewObservableLogSink creates a new observableEncoder and a sink that uses the encoder. +// func NewObservableLogSink() (*observableEncoder, Sink) { +// now := time.Now().UTC().Format(time.RFC3339) +// log.TimestampFunc = func() string { +// return now +// } +// +// te := &observableEncoder{} +// +// return te, sink.NewLogSink("", ioutil.Discard, 0, te) +// } diff --git a/internal/sink/sink.go b/internal/sink/sink.go index 661c322..28f7261 100644 --- a/internal/sink/sink.go +++ b/internal/sink/sink.go @@ -112,6 +112,22 @@ func (s *Sink) WithName(name string) logr.LogSink { return NewLogSink(newName, s.output, s.verbosity, s.encoder, s.context) } +// SetOutput sets the writer that JSON is written to +func (s *Sink) SetOutput(w io.Writer) { + s.mtx.Lock() + defer s.mtx.Unlock() + + s.output = w +} + +// SetVerbosity sets the log level allowed by the logsink +func (s *Sink) SetVerbosity(v int) { + s.mtx.Lock() + defer s.mtx.Unlock() + + s.verbosity = Verbosity(v) +} + // log will log the message. It DOES NOT check Enabled() first so that should // be checked by it's callers func (s *Sink) log(msg string, context map[string]interface{}) { diff --git a/internal/sink/sink_test.go b/internal/sink/sink_test.go new file mode 100644 index 0000000..17329b9 --- /dev/null +++ b/internal/sink/sink_test.go @@ -0,0 +1,538 @@ +package sink_test +// +// import ( +// "bytes" +// "encoding/json" +// "fmt" +// "io" +// "io/ioutil" +// "math" +// "reflect" +// "testing" +// +// "github.com/ViaQ/logerr/v2/kverrors" +// "github.com/ViaQ/logerr/v2/log" +// "github.com/go-logr/logr" +// "github.com/stretchr/testify/assert" +// "github.com/stretchr/testify/require" +// ) +// +// func TestLogger_Info_WithKeysAndValues(t *testing.T) { +// obs, logger := NewObservedLogger() +// +// logger.Info("hello, world", "city", "Athens") +// +// logs := obs.TakeAll() +// assert.Len(t, logs, 1) +// assert.EqualValues(t, "hello, world", logs[0].Message) +// +// assertLoggedFields(t, +// logs[0], +// Fields{ +// "city": "Athens", +// }, +// ) +// } +// +// func TestLogger_Error_noKeysAndValues(t *testing.T) { +// obs, logger := NewObservedLogger() +// +// err := kverrors.New("an error") +// logger.Error(err, "hello, world") +// +// logs := obs.TakeAll() +// require.Len(t, logs, 1) +// require.EqualValues(t, "hello, world", logs[0].Message) +// require.EqualValues(t, err, logs[0].Error) +// } +// +// var unsupportedValues = []float64{ +// math.NaN(), +// math.Inf(-1), +// math.Inf(1), +// } +// +// func TestLogger_Info_UnsupportedValues(t *testing.T) { +// for _, unsupportedValue := range unsupportedValues { +// buf := bytes.NewBuffer(nil) +// logger := logr.New(log.NewLogSink("", buf, 0, log.JSONEncoder{})) +// logger.Info("Test unsupported value", "value", unsupportedValue) +// +// if buf.Len() == 0 { +// t.Fatal("expected log output, but buffer was empty") +// } +// assert.Contains(t, string(buf.Bytes()), "failed to encode message") +// assert.Contains(t, string(buf.Bytes()), fmt.Sprintf("json: unsupported value: %f", unsupportedValue)) +// } +// } +// +// func TestLogger_Error_UnsupportedValues(t *testing.T) { +// for _, unsupportedValue := range unsupportedValues { +// buf := bytes.NewBuffer(nil) +// logger := log.NewLogSink("", buf, 0, log.JSONEncoder{}) +// err := kverrors.New("an error") +// logger.Error(err, "Test unsupported value", "key", unsupportedValue) +// +// if buf.Len() == 0 { +// t.Fatal("expected log output, but buffer was empty") +// } +// println(string(buf.Bytes())) +// assert.Contains(t, string(buf.Bytes()), "failed to encode message") +// assert.Contains(t, string(buf.Bytes()), fmt.Sprintf("json: unsupported value: %f", unsupportedValue)) +// } +// } +// +// func TestLogger_Error_KeysAndValues(t *testing.T) { +// obs, logger := NewObservedLogger() +// +// err := kverrors.New("an error") +// logger.Error(err, "hello, world", "key", "value") +// +// logs := obs.TakeAll() +// require.Len(t, logs, 1) +// require.EqualValues(t, "hello, world", logs[0].Message) +// +// assertLoggedFields(t, +// logs[0], +// Fields{ +// "key": "value", +// }, +// ) +// } +// +// func TestLogger_Error_pkg_error_KeysAndValues(t *testing.T) { +// obs, logger := NewObservedLogger() +// +// err := kverrors.New("an error", "key", "value") +// logger.Error(err, "hello, world") +// +// logs := obs.TakeAll() +// assert.Len(t, logs, 1) +// assert.EqualValues(t, "hello, world", logs[0].Message) +// require.EqualValues(t, err, logs[0].Error) +// +// assertLoggedFields(t, +// logs[0], +// Fields{ +// log.MessageKey: "hello, world", +// log.ErrorKey: map[string]interface{}{ +// "msg": "an error", +// "key": "value", +// }, +// }, +// ) +// } +// +// func TestLogger_Error_nested_error(t *testing.T) { +// obs, logger := NewObservedLogger() +// +// err1 := kverrors.New("error1", "order", 1) +// err := kverrors.Wrap(err1, "main error", "key", "value") +// logger.Error(err, "hello, world") +// +// logs := obs.TakeAll() +// assert.Len(t, logs, 1) +// assert.EqualValues(t, "hello, world", logs[0].Message) +// +// assertLoggedFields(t, +// logs[0], +// Fields{ +// log.ErrorKey: map[string]interface{}{ +// "key": "value", +// "msg": kverrors.Message(err), +// kverrors.CauseKey: map[string]interface{}{ +// "order": 1, +// "msg": kverrors.Message(err1), +// }, +// }, +// }, +// ) +// } +// +// func TestLogger__PlainErrors_ConvertedToStructured(t *testing.T) { +// obs, logger := NewObservedLogger() +// +// err := io.ErrClosedPipe +// logger.Error(err, "hello, world") +// +// logs := obs.TakeAll() +// assert.Len(t, logs, 1) +// assert.EqualValues(t, "hello, world", logs[0].Message) +// +// assertLoggedFields(t, +// logs[0], +// Fields{ +// log.ErrorKey: map[string]interface{}{ +// "msg": err.Error(), +// }, +// }, +// ) +// } +// +// func TestLogger_WithValues_AddsValues(t *testing.T) { +// obs, logger := NewObservedLogger() +// +// err := io.ErrClosedPipe +// ll := logger.WithValues("key", "value") +// +// ll.Error(err, "hello, world") +// +// logs := obs.TakeAll() +// assert.Len(t, logs, 1) +// assert.EqualValues(t, "hello, world", logs[0].Message) +// +// assertLoggedFields(t, +// logs[0], +// Fields{ +// "key": "value", +// }, +// ) +// } +// +// func TestLogger_Error_MakesUnstructuredErrorsStructured(t *testing.T) { +// obs, logger := NewObservedLogger() +// +// logger.Error(io.ErrClosedPipe, t.Name()) +// +// logs := obs.TakeAll() +// assert.Len(t, logs, 1) +// +// assertLoggedFields(t, +// logs[0], +// Fields{ +// log.ErrorKey: map[string]interface{}{ +// "msg": io.ErrClosedPipe.Error(), +// }, +// }, +// ) +// } +// +// func TestLogger_Error_WorksWithNilError(t *testing.T) { +// obs, logger := NewObservedLogger() +// +// logger.Error(nil, t.Name()) +// +// logs := obs.TakeAll() +// assert.Len(t, logs, 1) +// assert.Nil(t, logs[0].Error) +// } +// +// func TestLogger_V_Info(t *testing.T) { +// // loop through log levels 1-5 and log all of them to verify that they either +// // are or are not logged according to verbosity above +// for verbosity := 1; verbosity < 5; verbosity++ { +// for logLevel := 1; logLevel < 5; logLevel++ { +// obs, logger := NewObservedLogger() +// logger.GetSink().(*log.Sink).SetVerbosity(verbosity) +// +// logger.V(logLevel).Info("hello, world") +// +// logs := obs.TakeAll() +// +// if verbosity >= logLevel { +// assert.Len(t, logs, 1, "expected log to be present for verbosity:%d, logLevel:%d", verbosity, logLevel) +// assert.EqualValues(t, "hello, world", logs[0].Message) +// } else { +// assert.Empty(t, logs, "expected NO logs to be present for verbosity:%d, logLevel:%d", verbosity, logLevel) +// } +// } +// } +// } +// +// func TestLogger_V_Error(t *testing.T) { +// // Error messages should always be logged regardless of level +// for verbosity := 1; verbosity < 5; verbosity++ { +// for logLevel := 1; logLevel < 5; logLevel++ { +// obs, logger := NewObservedLogger() +// logger.GetSink().(*log.Sink).SetVerbosity(verbosity) +// +// logger.V(logLevel).Error(io.ErrUnexpectedEOF, "hello, world") +// +// logs := obs.TakeAll() +// +// assert.Len(t, logs, 1, "expected log to be present for verbosity:%d, logLevel:%d", verbosity, logLevel) +// assert.EqualValues(t, "hello, world", logs[0].Message) +// } +// } +// } +// +// func TestLogger_SetsVerbosity(t *testing.T) { +// obs, logger := NewObservedLogger() +// +// logger.Info(t.Name()) +// +// logs := obs.TakeAll() +// assert.Len(t, logs, 1) +// assert.EqualValues(t, 0, logs[0].Verbosity) +// } +// +// func TestLogger_TestSetOutput(t *testing.T) { +// buf := bytes.NewBuffer(nil) +// +// s := log.NewLogSink("", ioutil.Discard, 0, log.JSONEncoder{}) +// s.SetOutput(buf) +// +// logger := logr.New(s) +// +// msg := "hello, world" +// logger.Info(msg) +// +// if buf.Len() == 0 { +// t.Fatal("expected log output, but buffer was empty") +// } +// assert.Contains(t, string(buf.Bytes()), fmt.Sprintf(`%q:%q`, log.MessageKey, msg)) +// } +// +// func TestLogger_Info_PrintsError_WhenEncoderErrors(t *testing.T) { +// err := io.ErrShortBuffer +// fenc := fakeEncoder{ +// EncodeFunc: func(_ io.Writer, _ interface{}) error { +// return &json.MarshalerError{ +// Type: reflect.TypeOf(&json.MarshalerError{}), +// Err: err, +// } +// }, +// } +// +// buf := bytes.NewBuffer(nil) +// logger := logr.New(log.NewLogSink("", buf, 0, fenc)) +// +// msg := "hello, world" +// logger.Info(msg) +// +// if buf.Len() == 0 { +// t.Fatal("expected buffer output, but buffer was empty") +// } +// +// output := string(buf.Bytes()) +// assert.Contains(t, output, msg, "has the original message") +// assert.Contains(t, output, err.Error(), "shows the original error") +// assert.Contains(t, output, reflect.TypeOf(fenc).String(), "explains the encoder that failed") +// } +// +// func TestLogger_LogsLevel(t *testing.T) { +// const v = 2 +// +// obs, logger := NewObservedLogger() +// logger.GetSink().(*log.Sink).SetVerbosity(v) +// +// logger.V(v).Info("hello, world", "city", "Athens") +// +// logs := obs.TakeAll() +// assert.Len(t, logs, 1) +// assert.EqualValues(t, "hello, world", logs[0].Message) +// +// assertLoggedFields(t, +// logs[0], +// Fields{ +// log.LevelKey: v, +// }, +// ) +// } +// +// func TestLogger_ProductionLogsLevel(t *testing.T) { +// const v = 0 +// +// buf := bytes.NewBuffer(nil) +// s := log.NewLogSink("", ioutil.Discard, v, log.JSONEncoder{}) +// s.SetOutput(buf) +// +// msg := "hello, world" +// logger := logr.New(s) +// +// logger.Info(msg) +// +// if buf.Len() == 0 { +// t.Fatal("expected log output, but buffer was empty") +// } +// assert.Contains(t, string(buf.Bytes()), fmt.Sprintf(`%q:%q`, log.MessageKey, msg)) +// assert.NotContains(t, string(buf.Bytes()), fmt.Sprintf(`%q`, log.FileLineKey)) +// } +// +// func TestLogger_DeveloperLogsLevel(t *testing.T) { +// const v = 2 +// +// buf := bytes.NewBuffer(nil) +// s := log.NewLogSink("", ioutil.Discard, v, log.JSONEncoder{}) +// s.SetOutput(buf) +// +// msg := "hello, world" +// logger := logr.New(s) +// +// logger.Info(msg) +// +// if buf.Len() == 0 { +// t.Fatal("expected log output, but buffer was empty") +// } +// assert.Contains(t, string(buf.Bytes()), fmt.Sprintf(`%q:%q`, log.MessageKey, msg)) +// assert.Contains(t, string(buf.Bytes()), fmt.Sprintf(`%q`, log.FileLineKey)) +// } +// +// func TestLogger_LogLineWithNoContext(t *testing.T) { +// msg := "hello, world" +// l := log.Line{ +// Message: msg, +// } +// +// buf, err := l.MarshalJSON() +// assert.Nil(t, err) +// assert.Contains(t, string(buf), fmt.Sprintf(`%q:%q`, log.MessageKey, msg)) +// } +// +// func TestSetOutput(t *testing.T) { +// obs, l := NewObservedLogger() +// s, err := log.GetSink(l) +// +// require.NoError(t, err) +// +// msg := t.Name() +// buf := bytes.NewBuffer(nil) +// +// s.SetOutput(buf) +// +// l.Info(msg) +// logs := obs.TakeAll() +// +// require.NotEmpty(t, logs) +// require.Contains(t, logs[0].Message, msg) +// } +// +// func TestSetLogLevel(t *testing.T) { +// obs, l := NewObservedLogger() +// s, err := log.GetSink(l) +// +// require.NoError(t, err) +// +// const logLevel = 4 +// msg := t.Name() +// +// s.SetVerbosity(logLevel) +// l.V(logLevel).Info(msg) +// +// logs := obs.TakeAll() +// require.NotEmpty(t, logs) +// +// require.EqualValues(t, msg, logs[0].Message) +// } + + + +// func TestNewLogger_WithOptionsVerbosity(t *testing.T) { +// component := "mycomponent" +// buf := bytes.NewBuffer(nil) +// +// opts := log.Options{Writer: buf, LogLevel: 2} +// l := log.NewLoggerWithOptions(component, &opts) +// +// l.Info("laskdjfhiausdc") +// +// expected := fmt.Sprintf(`%q:%q`, sink.ComponentKey, component) +// actual := string(buf.Bytes()) +// +// fmt.Println(actual) +// +// require.Contains(t, actual, expected) +// } +// +// func TestInfo(t *testing.T) { +// obs, l := NewObservedLogger() +// +// msg := t.Name() +// l.Info(msg) +// +// logs := obs.Logs() +// require.Len(t, logs, 1) +// require.EqualValues(t, msg, logs[0].Message) +// } +// +// func TestError(t *testing.T) { +// obs, l := NewObservedLogger() +// +// msg := t.Name() +// err := errors.New("fail boat") +// +// l.Error(err, msg) +// +// logs := obs.Logs() +// require.Len(t, logs, 1) +// require.EqualValues(t, msg, logs[0].Message) +// require.NotNil(t, logs[0].Error) +// require.EqualValues(t, err.Error(), logs[0].Error.Error()) +// } +// +// func TestWithValues(t *testing.T) { +// obs, l := NewObservedLogger() +// +// msg := t.Name() +// ll := l.WithValues("hello", "world") +// +// t.Run("Error", func(t *testing.T) { +// ll.Error(errors.New("fail boat"), msg) +// logs := obs.TakeAll() +// require.Len(t, logs, 1) +// assert.EqualValues(t, msg, logs[0].Message) +// assert.EqualValues(t, kv.ToMap("hello", "world"), logs[0].Context) +// }) +// +// t.Run("Info", func(t *testing.T) { +// ll.Info(msg, "a", "b") +// ll.Info(msg, "c", "d") +// logs := obs.TakeAll() +// require.Len(t, logs, 2) +// assert.EqualValues(t, msg, logs[0].Message) +// assert.EqualValues(t, kv.ToMap("a", "b", "hello", "world"), logs[0].Context) +// assert.EqualValues(t, kv.ToMap("c", "d", "hello", "world"), logs[1].Context) +// }) +// } +// +// func TestWithName(t *testing.T) { +// obs, _ := NewObservedLogger() +// +// l := logr.New(log.NewLogSink("", ioutil.Discard, 0, obs)).WithName("mycomponent") +// ll := l.WithName("mynameis") +// +// msg := t.Name() +// ll.Info(msg) +// +// logs := obs.TakeAll() +// require.NotEmpty(t, logs) +// +// require.Contains(t, logs[0].Component, "mycomponent") +// require.Contains(t, logs[0].Component, "mynameis") +// } +// +// func TestV(t *testing.T) { +// obs, l := NewObservedLogger() +// s, err := log.GetSink(l) +// +// require.NoError(t, err) +// +// msg := t.Name() +// +// s.SetVerbosity(1) +// l.V(1).Info(msg) +// +// logs := obs.TakeAll() +// require.NotEmpty(t, logs) +// require.Equal(t, msg, logs[0].Message) +// } +// +// // This test exists to confirm that the output actually works. There was a previous bug that broke the real logger +// // because DefaultConfig specified a sampling which caused a panic. This uses a real logger and logs just to verify +// // that it _can_ log successfully. There are no assertions because the content of the logs are irrelevant. See +// // TestLogger_V above for a more comprehensive test. +// func TestLogger_V_Integration(t *testing.T) { +// for i := 1; i < 5; i++ { +// verbosity := i +// testName := fmt.Sprintf("verbosity-%d", verbosity) +// +// opts := Options{Writer: ioutil.Discard, LogLevel: verbosity} +// l := log.NewLoggerWithOptions(testName, opts) +// +// t.Run(testName, func(t *testing.T) { +// for logLevel := 1; logLevel < 5; logLevel++ { +// l.V(logLevel).Info("hello, world") +// } +// }) +// } +// } diff --git a/log/fakes_test.go b/log/fakes_test.go deleted file mode 100644 index 12fbf45..0000000 --- a/log/fakes_test.go +++ /dev/null @@ -1,28 +0,0 @@ -package log_test - -import ( - "github.com/go-logr/logr" -) - -type nopLogSink struct{} - -func (nopLogSink) Init(logr.RuntimeInfo) { -} - -func (nopLogSink) Enabled(int) bool { - return false -} - -func (nopLogSink) Info(int, string, ...interface{}) { -} - -func (nopLogSink) Error(error, string, ...interface{}) { -} - -func (nopLogSink) WithValues(...interface{}) logr.LogSink { - return nil -} - -func (nopLogSink) WithName(string) logr.LogSink { - return nil -} diff --git a/log/log.go b/log/log.go index 06a8e4e..94aaf07 100644 --- a/log/log.go +++ b/log/log.go @@ -1,7 +1,6 @@ package log import ( - "io" "os" "github.com/ViaQ/logerr/v2/internal/sink" @@ -10,26 +9,23 @@ import ( // NewLogger creates a logger with the provided key value pairs func NewLogger(component string, keyValuePairs ...interface{}) logr.Logger { - return NewLoggerWithOptions(component, Options{}, keyValuePairs...) + return NewLoggerWithOptions(component, nil, keyValuePairs...) } // NewLoggerWithOptions creates a logger with the provided opts and key value pairs -func NewLoggerWithOptions(component string, opts Options, keyValuePairs ...interface{}) logr.Logger { - level := 0 - var writer io.Writer = os.Stdout +func NewLoggerWithOptions(component string, opts *Options, keyValuePairs ...interface{}) logr.Logger { + sinkOpts := Options{Writer: os.Stdout, LogLevel: 0} - if opts.LogLevel != nil { - level = *(opts.LogLevel) - } - if opts.Writer != nil { - writer = *(opts.Writer) + if opts != nil { + sinkOpts.Writer = opts.Writer + sinkOpts.LogLevel = opts.LogLevel } return logr.New( sink.NewLogSink( component, - writer, - sink.Verbosity(level), + sinkOpts.Writer, + sink.Verbosity(sinkOpts.LogLevel), sink.JSONEncoder{}, keyValuePairs..., ), diff --git a/log/log_test.go b/log/log_test.go index 95a74c8..cd4d5e7 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -2,181 +2,53 @@ package log_test import ( "bytes" - "errors" + // "errors" "fmt" - "github.com/ViaQ/logerr/v2/internal/kv" + // "github.com/ViaQ/logerr/v2/internal/kv" - "io/ioutil" + // "io/ioutil" "testing" - "github.com/ViaQ/logerr/v2/kverrors" + // "github.com/ViaQ/logerr/v2/kverrors" "github.com/ViaQ/logerr/v2/log" - "github.com/go-logr/logr" - "github.com/stretchr/testify/assert" + "github.com/ViaQ/logerr/v2/internal/sink" + // "github.com/go-logr/logr" + // "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) -// This test exists to confirm that the output actually works. There was a previous bug that broke the real logger -// because DefaultConfig specified a sampling which caused a panic. This uses a real logger and logs just to verify -// that it _can_ log successfully. There are no assertions because the content of the logs are irrelevant. See -// TestLogger_V above for a more comprehensive test. -func TestLogger_V_Integration(t *testing.T) { - for i := 1; i < 5; i++ { - verbosity := i - testName := fmt.Sprintf("verbosity-%d", verbosity) - l := log.NewLoggerWithOptions(testName, []log.Option{ - log.WithOutput(ioutil.Discard), - log.WithLogLevel(verbosity), - }) - t.Run(testName, func(t *testing.T) { - for logLevel := 1; logLevel < 5; logLevel++ { - l.V(logLevel).Info("hello, world") - } - }) - } -} - func TestNewLogger(t *testing.T) { component := "mycomponent" buf := bytes.NewBuffer(nil) - l := log.NewLogger(component) - s, err := log.GetSink(l) - - require.NoError(t, err) - + l := log.NewLoggerWithOptions(component, nil) + s := l.GetSink().(*sink.Sink) s.SetOutput(buf) - l.Info("laskdjfhiausdc") - - expected := fmt.Sprintf(`%q:%q`, log.ComponentKey, component) - actual := string(buf.Bytes()) - - require.Contains(t, actual, expected) -} - -func TestInfo(t *testing.T) { - obs, l := NewObservedLogger() - - msg := t.Name() - l.Info(msg) - - logs := obs.Logs() - require.Len(t, logs, 1) - require.EqualValues(t, msg, logs[0].Message) -} - -func TestError(t *testing.T) { - obs, l := NewObservedLogger() - - msg := t.Name() - err := errors.New("fail boat") - - l.Error(err, msg) - - logs := obs.Logs() - require.Len(t, logs, 1) - require.EqualValues(t, msg, logs[0].Message) - require.NotNil(t, logs[0].Error) - require.EqualValues(t, err.Error(), logs[0].Error.Error()) -} - -func TestWithValues(t *testing.T) { - obs, l := NewObservedLogger() - - msg := t.Name() - ll := l.WithValues("hello", "world") - - t.Run("Error", func(t *testing.T) { - ll.Error(errors.New("fail boat"), msg) - logs := obs.TakeAll() - require.Len(t, logs, 1) - assert.EqualValues(t, msg, logs[0].Message) - assert.EqualValues(t, kv.ToMap("hello", "world"), logs[0].Context) - }) - - t.Run("Info", func(t *testing.T) { - ll.Info(msg, "a", "b") - ll.Info(msg, "c", "d") - logs := obs.TakeAll() - require.Len(t, logs, 2) - assert.EqualValues(t, msg, logs[0].Message) - assert.EqualValues(t, kv.ToMap("a", "b", "hello", "world"), logs[0].Context) - assert.EqualValues(t, kv.ToMap("c", "d", "hello", "world"), logs[1].Context) - }) -} - -func TestSetLogLevel(t *testing.T) { - obs, l := NewObservedLogger() - s, err := log.GetSink(l) - require.NoError(t, err) - - const logLevel = 4 - msg := t.Name() - - s.SetVerbosity(logLevel) - l.V(logLevel).Info(msg) + l.Info("laskdjfhiausdc") + msg := string(buf.Bytes()) - logs := obs.TakeAll() - require.NotEmpty(t, logs) + componentValue := fmt.Sprintf(`%q:%q`, sink.ComponentKey, component) + levelValue := fmt.Sprintf(`%q:"%d"`, sink.LevelKey, 0) - require.EqualValues(t, msg, logs[0].Message) + require.Contains(t, msg, componentValue) + require.Contains(t, msg, levelValue) } -func TestSetOutput(t *testing.T) { - obs, l := NewObservedLogger() - s, err := log.GetSink(l) - - require.NoError(t, err) - - msg := t.Name() +func TestNewLogger_WithOptions(t *testing.T) { + level := 1 + component := "mycomponent" buf := bytes.NewBuffer(nil) - s.SetOutput(buf) - - l.Info(msg) - logs := obs.TakeAll() - - require.NotEmpty(t, logs) - require.Contains(t, logs[0].Message, msg) -} - -func TestGetSink_WithUnknownLogSink_Errors(t *testing.T) { - l := logr.New(nopLogSink{}) - _, err := log.GetSink(l) + opts := log.Options{Writer: buf, LogLevel: level} + l := log.NewLoggerWithOptions(component, &opts) - actual := kverrors.Root(err) - require.Equal(t, log.ErrUnknownSinkType, actual) -} - -func TestWithName(t *testing.T) { - obs, _ := NewObservedLogger() - - l := logr.New(log.NewLogSink("", ioutil.Discard, 0, obs)).WithName("mycomponent") - ll := l.WithName("mynameis") - - msg := t.Name() - ll.Info(msg) - - logs := obs.TakeAll() - require.NotEmpty(t, logs) - - require.Contains(t, logs[0].Component, "mycomponent") - require.Contains(t, logs[0].Component, "mynameis") -} - -func TestV(t *testing.T) { - obs, l := NewObservedLogger() - s, err := log.GetSink(l) - - require.NoError(t, err) - - msg := t.Name() + l.Info("laskdjfhiausdc") + msg := string(buf.Bytes()) - s.SetVerbosity(1) - l.V(1).Info(msg) + componentValue := fmt.Sprintf(`%q:%q`, sink.ComponentKey, component) + levelValue := fmt.Sprintf(`%q:"%d"`, sink.LevelKey, level) - logs := obs.TakeAll() - require.NotEmpty(t, logs) - require.Equal(t, msg, logs[0].Message) + require.Contains(t, msg, componentValue) + require.Contains(t, msg, levelValue) } diff --git a/log/logsink_test.go b/log/logsink_test.go deleted file mode 100644 index a7790d5..0000000 --- a/log/logsink_test.go +++ /dev/null @@ -1,380 +0,0 @@ -package log_test - -import ( - "bytes" - "encoding/json" - "fmt" - "io" - "io/ioutil" - "math" - "reflect" - "testing" - - "github.com/ViaQ/logerr/v2/kverrors" - "github.com/ViaQ/logerr/v2/log" - "github.com/go-logr/logr" - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" -) - -func TestLogger_Info_WithKeysAndValues(t *testing.T) { - obs, logger := NewObservedLogger() - - logger.Info("hello, world", "city", "Athens") - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.EqualValues(t, "hello, world", logs[0].Message) - - assertLoggedFields(t, - logs[0], - Fields{ - "city": "Athens", - }, - ) -} - -func TestLogger_Error_noKeysAndValues(t *testing.T) { - obs, logger := NewObservedLogger() - - err := kverrors.New("an error") - logger.Error(err, "hello, world") - - logs := obs.TakeAll() - require.Len(t, logs, 1) - require.EqualValues(t, "hello, world", logs[0].Message) - require.EqualValues(t, err, logs[0].Error) -} - -var unsupportedValues = []float64{ - math.NaN(), - math.Inf(-1), - math.Inf(1), -} - -func TestLogger_Info_UnsupportedValues(t *testing.T) { - for _, unsupportedValue := range unsupportedValues { - buf := bytes.NewBuffer(nil) - logger := logr.New(log.NewLogSink("", buf, 0, log.JSONEncoder{})) - logger.Info("Test unsupported value", "value", unsupportedValue) - - if buf.Len() == 0 { - t.Fatal("expected log output, but buffer was empty") - } - assert.Contains(t, string(buf.Bytes()), "failed to encode message") - assert.Contains(t, string(buf.Bytes()), fmt.Sprintf("json: unsupported value: %f", unsupportedValue)) - } -} - -func TestLogger_Error_UnsupportedValues(t *testing.T) { - for _, unsupportedValue := range unsupportedValues { - buf := bytes.NewBuffer(nil) - logger := log.NewLogSink("", buf, 0, log.JSONEncoder{}) - err := kverrors.New("an error") - logger.Error(err, "Test unsupported value", "key", unsupportedValue) - - if buf.Len() == 0 { - t.Fatal("expected log output, but buffer was empty") - } - println(string(buf.Bytes())) - assert.Contains(t, string(buf.Bytes()), "failed to encode message") - assert.Contains(t, string(buf.Bytes()), fmt.Sprintf("json: unsupported value: %f", unsupportedValue)) - } -} - -func TestLogger_Error_KeysAndValues(t *testing.T) { - obs, logger := NewObservedLogger() - - err := kverrors.New("an error") - logger.Error(err, "hello, world", "key", "value") - - logs := obs.TakeAll() - require.Len(t, logs, 1) - require.EqualValues(t, "hello, world", logs[0].Message) - - assertLoggedFields(t, - logs[0], - Fields{ - "key": "value", - }, - ) -} - -func TestLogger_Error_pkg_error_KeysAndValues(t *testing.T) { - obs, logger := NewObservedLogger() - - err := kverrors.New("an error", "key", "value") - logger.Error(err, "hello, world") - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.EqualValues(t, "hello, world", logs[0].Message) - require.EqualValues(t, err, logs[0].Error) - - assertLoggedFields(t, - logs[0], - Fields{ - log.MessageKey: "hello, world", - log.ErrorKey: map[string]interface{}{ - "msg": "an error", - "key": "value", - }, - }, - ) -} - -func TestLogger_Error_nested_error(t *testing.T) { - obs, logger := NewObservedLogger() - - err1 := kverrors.New("error1", "order", 1) - err := kverrors.Wrap(err1, "main error", "key", "value") - logger.Error(err, "hello, world") - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.EqualValues(t, "hello, world", logs[0].Message) - - assertLoggedFields(t, - logs[0], - Fields{ - log.ErrorKey: map[string]interface{}{ - "key": "value", - "msg": kverrors.Message(err), - kverrors.CauseKey: map[string]interface{}{ - "order": 1, - "msg": kverrors.Message(err1), - }, - }, - }, - ) -} - -func TestLogger__PlainErrors_ConvertedToStructured(t *testing.T) { - obs, logger := NewObservedLogger() - - err := io.ErrClosedPipe - logger.Error(err, "hello, world") - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.EqualValues(t, "hello, world", logs[0].Message) - - assertLoggedFields(t, - logs[0], - Fields{ - log.ErrorKey: map[string]interface{}{ - "msg": err.Error(), - }, - }, - ) -} - -func TestLogger_WithValues_AddsValues(t *testing.T) { - obs, logger := NewObservedLogger() - - err := io.ErrClosedPipe - ll := logger.WithValues("key", "value") - - ll.Error(err, "hello, world") - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.EqualValues(t, "hello, world", logs[0].Message) - - assertLoggedFields(t, - logs[0], - Fields{ - "key": "value", - }, - ) -} - -func TestLogger_Error_MakesUnstructuredErrorsStructured(t *testing.T) { - obs, logger := NewObservedLogger() - - logger.Error(io.ErrClosedPipe, t.Name()) - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - - assertLoggedFields(t, - logs[0], - Fields{ - log.ErrorKey: map[string]interface{}{ - "msg": io.ErrClosedPipe.Error(), - }, - }, - ) -} - -func TestLogger_Error_WorksWithNilError(t *testing.T) { - obs, logger := NewObservedLogger() - - logger.Error(nil, t.Name()) - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.Nil(t, logs[0].Error) -} - -func TestLogger_V_Info(t *testing.T) { - // loop through log levels 1-5 and log all of them to verify that they either - // are or are not logged according to verbosity above - for verbosity := 1; verbosity < 5; verbosity++ { - for logLevel := 1; logLevel < 5; logLevel++ { - obs, logger := NewObservedLogger() - logger.GetSink().(*log.Sink).SetVerbosity(verbosity) - - logger.V(logLevel).Info("hello, world") - - logs := obs.TakeAll() - - if verbosity >= logLevel { - assert.Len(t, logs, 1, "expected log to be present for verbosity:%d, logLevel:%d", verbosity, logLevel) - assert.EqualValues(t, "hello, world", logs[0].Message) - } else { - assert.Empty(t, logs, "expected NO logs to be present for verbosity:%d, logLevel:%d", verbosity, logLevel) - } - } - } -} - -func TestLogger_V_Error(t *testing.T) { - // Error messages should always be logged regardless of level - for verbosity := 1; verbosity < 5; verbosity++ { - for logLevel := 1; logLevel < 5; logLevel++ { - obs, logger := NewObservedLogger() - logger.GetSink().(*log.Sink).SetVerbosity(verbosity) - - logger.V(logLevel).Error(io.ErrUnexpectedEOF, "hello, world") - - logs := obs.TakeAll() - - assert.Len(t, logs, 1, "expected log to be present for verbosity:%d, logLevel:%d", verbosity, logLevel) - assert.EqualValues(t, "hello, world", logs[0].Message) - } - } -} - -func TestLogger_SetsVerbosity(t *testing.T) { - obs, logger := NewObservedLogger() - - logger.Info(t.Name()) - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.EqualValues(t, 0, logs[0].Verbosity) -} - -func TestLogger_TestSetOutput(t *testing.T) { - buf := bytes.NewBuffer(nil) - - s := log.NewLogSink("", ioutil.Discard, 0, log.JSONEncoder{}) - s.SetOutput(buf) - - logger := logr.New(s) - - msg := "hello, world" - logger.Info(msg) - - if buf.Len() == 0 { - t.Fatal("expected log output, but buffer was empty") - } - assert.Contains(t, string(buf.Bytes()), fmt.Sprintf(`%q:%q`, log.MessageKey, msg)) -} - -func TestLogger_Info_PrintsError_WhenEncoderErrors(t *testing.T) { - err := io.ErrShortBuffer - fenc := fakeEncoder{ - EncodeFunc: func(_ io.Writer, _ interface{}) error { - return &json.MarshalerError{ - Type: reflect.TypeOf(&json.MarshalerError{}), - Err: err, - } - }, - } - - buf := bytes.NewBuffer(nil) - logger := logr.New(log.NewLogSink("", buf, 0, fenc)) - - msg := "hello, world" - logger.Info(msg) - - if buf.Len() == 0 { - t.Fatal("expected buffer output, but buffer was empty") - } - - output := string(buf.Bytes()) - assert.Contains(t, output, msg, "has the original message") - assert.Contains(t, output, err.Error(), "shows the original error") - assert.Contains(t, output, reflect.TypeOf(fenc).String(), "explains the encoder that failed") -} - -func TestLogger_LogsLevel(t *testing.T) { - const v = 2 - - obs, logger := NewObservedLogger() - logger.GetSink().(*log.Sink).SetVerbosity(v) - - logger.V(v).Info("hello, world", "city", "Athens") - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.EqualValues(t, "hello, world", logs[0].Message) - - assertLoggedFields(t, - logs[0], - Fields{ - log.LevelKey: v, - }, - ) -} - -func TestLogger_ProductionLogsLevel(t *testing.T) { - const v = 0 - - buf := bytes.NewBuffer(nil) - s := log.NewLogSink("", ioutil.Discard, v, log.JSONEncoder{}) - s.SetOutput(buf) - - msg := "hello, world" - logger := logr.New(s) - - logger.Info(msg) - - if buf.Len() == 0 { - t.Fatal("expected log output, but buffer was empty") - } - assert.Contains(t, string(buf.Bytes()), fmt.Sprintf(`%q:%q`, log.MessageKey, msg)) - assert.NotContains(t, string(buf.Bytes()), fmt.Sprintf(`%q`, log.FileLineKey)) -} - -func TestLogger_DeveloperLogsLevel(t *testing.T) { - const v = 2 - - buf := bytes.NewBuffer(nil) - s := log.NewLogSink("", ioutil.Discard, v, log.JSONEncoder{}) - s.SetOutput(buf) - - msg := "hello, world" - logger := logr.New(s) - - logger.Info(msg) - - if buf.Len() == 0 { - t.Fatal("expected log output, but buffer was empty") - } - assert.Contains(t, string(buf.Bytes()), fmt.Sprintf(`%q:%q`, log.MessageKey, msg)) - assert.Contains(t, string(buf.Bytes()), fmt.Sprintf(`%q`, log.FileLineKey)) -} - -func TestLogger_LogLineWithNoContext(t *testing.T) { - msg := "hello, world" - l := log.Line{ - Message: msg, - } - - buf, err := l.MarshalJSON() - assert.Nil(t, err) - assert.Contains(t, string(buf), fmt.Sprintf(`%q:%q`, log.MessageKey, msg)) -} diff --git a/log/observer_test.go b/log/observer_test.go deleted file mode 100644 index 59fed7a..0000000 --- a/log/observer_test.go +++ /dev/null @@ -1,164 +0,0 @@ -package log_test - -import ( - "bytes" - "encoding/json" - "fmt" - "io" - "io/ioutil" - "os" - "strconv" - "testing" - "time" - - "github.com/ViaQ/logerr/v2/kverrors" - "github.com/ViaQ/logerr/v2/log" - "github.com/go-logr/logr" - "github.com/stretchr/testify/require" -) - -type Fields map[string]interface{} - -// assertLoggedFields checks that all of fields exists in the entry. -func assertLoggedFields(t *testing.T, entry *observedEntry, fields Fields) { - var f []string - for k := range fields { - f = append(f, k) - } - - ctx := entry.Fields(f...) - - for k, v := range fields { - value, ok := ctx[k] - require.True(t, ok, "expected key '%s:%v' to exist in logged entry %+v", k, v, entry) - actual, e := json.Marshal(value) - require.NoError(t, e) - expected, e := json.Marshal(v) - require.NoError(t, e) - require.JSONEq(t, string(expected), string(actual), "key: %q", k) - } -} - -type observedEntry struct { - Component string - Message string - Timestamp string - Context map[string]interface{} - Error error - Verbosity log.Verbosity - FileLine string -} - -// Fields filters the entry to the specified fields and returns the result as a map. -// This will include all known/parsed fields (such as Message, Timestamp) as well as -// all Context items. -func (o *observedEntry) Fields(fields ...string) Fields { - entry := o.ToMap() - filtered := Fields{} - - for _, f := range fields { - filtered[f] = entry[f] - } - return filtered -} - -// RawFields drops all but the specified from the entry and returns the encoded result -func (o *observedEntry) RawFields(fields ...string) ([]byte, error) { - filtered := o.Fields(fields...) - b := bytes.NewBuffer(nil) - err := log.JSONEncoder{}.Encode(b, filtered) - return b.Bytes(), err -} - -func (o *observedEntry) ToMap() map[string]interface{} { - m := make(map[string]interface{}, len(o.Context)) - for k, v := range o.Context { - m[k] = v - } - m[log.ErrorKey] = o.Error - m[log.MessageKey] = o.Message - m[log.TimeStampKey] = o.Timestamp - m[log.ComponentKey] = o.Component - m[log.LevelKey] = o.Verbosity - m[log.FileLineKey] = o.FileLine - return m -} - -func (o *observedEntry) Raw() ([]byte, error) { - entry := o.ToMap() - - b := bytes.NewBuffer(nil) - err := log.JSONEncoder{}.Encode(b, entry) - return b.Bytes(), err -} - -// observableEncoder stores all entries in a buffer rather than encoding them to an output -type observableEncoder struct { - entries []*observedEntry -} - -// Encode stores all entries in a buffer rather than encoding them to an output -func (o *observableEncoder) Encode(_ io.Writer, m interface{}) error { - o.entries = append(o.entries, parseEntry(m)) - return nil -} - -// Logs returns all logs in the buffer -func (o *observableEncoder) Logs() []*observedEntry { - return o.entries -} - -// TakeAll returns all logs and clears the buffer -func (o *observableEncoder) TakeAll() []*observedEntry { - defer o.Reset() - return o.Logs() -} - -// Reset empties the buffer -func (o *observableEncoder) Reset() { - o.entries = make([]*observedEntry, 0) -} - -// parseEntry parses all known fields into the observedEntry struct and places -// everything else in the Context field -func parseEntry(entry interface{}) *observedEntry { - // Make a copy, don't alter the argument as a side effect. - m := entry.(log.Line) - verbosity, err := strconv.Atoi(m.Verbosity) - if err != nil { - log.NewLogger("").Error(err, "failed to parse string as verbosity") - } - - var resultErr error = nil - if errVal, ok := m.Context[log.ErrorKey]; ok { - if resultErr, ok = errVal.(error); !ok { - fmt.Fprintf(os.Stderr, "failed to parse error from message: %v\n", kverrors.New("malformed/missing key", "key", log.ErrorKey)) - } - } - delete(m.Context, log.ErrorKey) - - result := &observedEntry{ - Timestamp: m.Timestamp, - FileLine: m.FileLine, - Verbosity: log.Verbosity(verbosity), - Component: m.Component, - Message: m.Message, - Context: m.Context, - Error: resultErr, - } - - return result -} - -// NewObservedLogger creates a new observableEncoder and a logger that uses the encoder. -func NewObservedLogger() (*observableEncoder, logr.Logger) { - now := time.Now().UTC().Format(time.RFC3339) - log.TimestampFunc = func() string { - return now - } - - te := &observableEncoder{} - s := log.NewLogSink("", ioutil.Discard, 0, te) - - return te, logr.New(s) -} diff --git a/log/options.go b/log/options.go index b42f74f..2f8e4c4 100644 --- a/log/options.go +++ b/log/options.go @@ -6,6 +6,6 @@ import ( // Options is a configuration option type Options struct { - Writer *io.Writer - LogLevel *int + Writer io.Writer + LogLevel int }