diff --git a/internal/sink/fake_encoder_test.go b/internal/sink/fake_encoder_test.go deleted file mode 100644 index e09a0d6..0000000 --- a/internal/sink/fake_encoder_test.go +++ /dev/null @@ -1,17 +0,0 @@ -package log_test - -import ( - "io" -) - -// fakeEncoder is an encoder that you can use for testing -type fakeEncoder struct { - EncodeFunc func(w io.Writer, entry interface{}) error -} - -func (f fakeEncoder) Encode(w io.Writer, entry interface{}) error { - if f.EncodeFunc != nil { - return f.EncodeFunc(w, entry) - } - return nil -} diff --git a/internal/sink/line_test.go b/internal/sink/line_test.go new file mode 100644 index 0000000..846e4a5 --- /dev/null +++ b/internal/sink/line_test.go @@ -0,0 +1,96 @@ +package sink_test + +import ( + "fmt" + "testing" + + "github.com/ViaQ/logerr/v2/kverrors" + "github.com/ViaQ/logerr/v2/internal/sink" + "github.com/stretchr/testify/require" +) + +func TestLine_ProductionLogs(t *testing.T) { + // Logs with a level of 0 or 1 are considered to be production level logs + msg := "hello, world" + s, b := sinkWithBuffer("", 1) + + s.Info(0, msg) + logMsg := string(b.Bytes()) + + require.NotEmpty(t, logMsg) + require.Contains(t, logMsg, fmt.Sprintf(`%q:%q`, sink.MessageKey, msg)) + require.NotContains(t, logMsg, fmt.Sprintf(`%q`, sink.FileLineKey)) +} + +func TestLine_DeveloperLogs(t *testing.T) { + // Logs with a higher level than 1 are considered to be developer level logs + msg := "hello, world" + s, b := sinkWithBuffer("", 2) + + s.Info(1, msg) + logMsg := string(b.Bytes()) + + require.NotEmpty(t, logMsg) + require.Contains(t, logMsg, fmt.Sprintf(`%q:%q`, sink.MessageKey, msg)) + require.Contains(t, logMsg, fmt.Sprintf(`%q`, sink.FileLineKey)) +} + +func TestLine_WithNoContext(t *testing.T) { + msg := "hello, world" + l := sink.Line{Message: msg} + + b, err := l.MarshalJSON() + + require.NoError(t, err) + require.Contains(t, string(b), fmt.Sprintf(`%q:%q`, sink.MessageKey, msg)) +} + +func TestLine_LogLevel(t *testing.T) { + s, b := sinkWithBuffer("", 0) + + for level := 0; level < 5; level++ { + b.Reset() + s.SetVerbosity(level) + + s.Info(0, "hello, world") + + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:"%d"`, sink.LevelKey, level)) + } +} + +func TestLine_WithKVError(t *testing.T) { + err := kverrors.New("an error", "key", "value") + msg := "Error bypasses the enabled check." + + kverrMsg, _ := err.(*kverrors.KVError).MarshalJSON() + + msgValue := fmt.Sprintf(`%q:%q`, sink.MessageKey, msg) + errorValue := fmt.Sprintf(`%q:%v`, sink.ErrorKey, string(kverrMsg)) + + s, b := sinkWithBuffer("", 0) + + s.Error(err, msg) + + logMsg := string(b.Bytes()) + require.Contains(t, logMsg, msgValue) + require.Contains(t, logMsg, errorValue) +} + +func TestLine_WithNestedKVError(t *testing.T) { + err := kverrors.New("an error", "key", "value") + wrappedErr := kverrors.Wrap(err, "main error", "key", "value") + msg := "Error bypasses the enabled check." + + kverrMsg, _ := wrappedErr.(*kverrors.KVError).MarshalJSON() + + msgValue := fmt.Sprintf(`%q:%q`, sink.MessageKey, msg) + errorValue := fmt.Sprintf(`%q:%v`, sink.ErrorKey, string(kverrMsg)) + + s, b := sinkWithBuffer("", 0) + + s.Error(wrappedErr, msg) + + logMsg := string(b.Bytes()) + require.Contains(t, logMsg, msgValue) + require.Contains(t, logMsg, errorValue) +} diff --git a/internal/sink/observerable_test.go b/internal/sink/observerable_test.go deleted file mode 100644 index 50f56bc..0000000 --- a/internal/sink/observerable_test.go +++ /dev/null @@ -1,164 +0,0 @@ -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 28f7261..1b16b86 100644 --- a/internal/sink/sink.go +++ b/internal/sink/sink.go @@ -128,6 +128,11 @@ func (s *Sink) SetVerbosity(v int) { s.verbosity = Verbosity(v) } +// GetLevel returns the log level +func (s *Sink) GetVerbosity() int { + return int(s.verbosity) +} + // 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 index 17329b9..4acc65d 100644 --- a/internal/sink/sink_test.go +++ b/internal/sink/sink_test.go @@ -1,538 +1,227 @@ 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") -// } -// }) -// } -// } + +import ( + "bytes" + "fmt" + "io" + "math" + "testing" + + "github.com/ViaQ/logerr/v2/kverrors" + "github.com/ViaQ/logerr/v2/internal/sink" + "github.com/go-logr/logr" + "github.com/stretchr/testify/require" +) + +func TestSink_Enabled(t *testing.T) { + s, _ := sinkWithBuffer("", 0) + + require.True(t, s.Enabled(0)) + require.False(t, s.Enabled(1)) + + ss, _ := sinkWithBuffer("", 1) + + require.True(t, ss.Enabled(1)) + require.True(t, ss.Enabled(0)) + require.False(t, ss.Enabled(2)) +} + +func TestSink_Info(t *testing.T) { + msg := "Same or lower than current verbosity. This should be logged." + msgValue := fmt.Sprintf(`%q:%q`, sink.MessageKey, msg) + + s, b := sinkWithBuffer("", 0) + + s.Info(0, msg) + + logMsg := string(b.Bytes()) + require.Contains(t, logMsg, msgValue) + + // Reset the buffer to ensure to avoid false positive of message + b.Reset() + s.Info(0, msg, "hello", "world") + + logMsg = string(b.Bytes()) + require.Contains(t, logMsg, msgValue) + require.Contains(t, logMsg, fmt.Sprintf(`%q:%q`, "hello", "world")) +} + +func TestSink_Info_Enabled(t *testing.T) { + s, b := sinkWithBuffer("", 1) + + s.Info(2, "Above current verbosity. This should not be logged.") + require.Empty(t, b.Bytes()) + + s.Info(0, "Same or lower than current verbosity. This should be logged.") + require.NotEmpty(t, b.Bytes()) +} + +func TestSink_Error(t *testing.T) { + err := kverrors.New("an error") + msg := "Error bypasses the enabled check." + + kverrMsg, _ := err.(*kverrors.KVError).MarshalJSON() + + msgValue := fmt.Sprintf(`%q:%q`, sink.MessageKey, msg) + levelValue := fmt.Sprintf(`%q:"%d"`, sink.LevelKey, 0) + errorValue := fmt.Sprintf(`%q:%v`, sink.ErrorKey, string(kverrMsg)) + + s, b := sinkWithBuffer("", 0) + + s.Error(err, msg) + + logMsg := string(b.Bytes()) + require.NotEmpty(t, logMsg) + require.Contains(t, logMsg, msgValue) + require.Contains(t, logMsg, levelValue) + require.Contains(t, logMsg, errorValue) + + // Reset the buffer to ensure to avoid false positive of message + b.Reset() + + s.Error(err, msg, "hello", "world") + + logMsg = string(b.Bytes()) + require.NotEmpty(t, logMsg) + require.Contains(t, logMsg, msgValue) + require.Contains(t, logMsg, levelValue) + require.Contains(t, logMsg, errorValue) + require.Contains(t, logMsg, fmt.Sprintf(`%q:%q`, "hello", "world")) +} + +func TestSink_Error_Enabled(t *testing.T) { + // Use a logger to create a scenario in which the logger's + // level will be greater than the current verbosity. This means + // that info will not work. However, error should always work, regardless. + s, b := sinkWithBuffer("", 0) + + // Logger level: 2, Sink Verbosity: 0 + l := logr.New(s).V(2) + require.Equal(t, 0, s.GetVerbosity()) + + l.Info("Above current verbosity. This should not be logged.") + require.Empty(t, b.Bytes()) + + l.Error(kverrors.New("an error"), "Error bypasses the enabled check.") + require.NotEmpty(t, b.Bytes()) +} + +func TestSink_Error_WithNilError(t *testing.T) { + // Use a logger to create a scenario in which the logger's + // level will be greater than the current verbosity. This means + // that info will not work. However, error should always work, regardless. + s, b := sinkWithBuffer("", 0) + + s.Error(nil, "No error sent. This should be logged.") + msg := string(b.Bytes()) + + require.NotEmpty(t, msg) +} + +func TestSink_Error_WithNonKVError(t *testing.T) { + err := io.ErrClosedPipe + errValue := fmt.Sprintf(`%q:{"msg":%q}`, sink.ErrorKey, err.Error()) + + s, b := sinkWithBuffer("", 0, "hello", "world") + + s.Error(err, "hello, world") + msg := string(b.Bytes()) + + require.NotEmpty(t, msg) + require.Contains(t, msg, errValue) +} + +func TestSink_WithValues(t *testing.T) { + s, b := sinkWithBuffer("", 0, "hello", "world") + + s.Info(0, "First.") + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:%q`, "hello", "world")) + + ss := s.WithValues("foo", "bar") + + ss.Error(nil, "Second.") + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:%q`, "hello", "world")) + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:%q`, "foo", "bar")) +} + +func TestSink_WithName(t *testing.T) { + s, b := sinkWithBuffer("new", 0) + + s.Info(0, "First.") + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:%q`, sink.ComponentKey, "new")) + + ss := s.WithName("append") + + ss.Info(0, "Second.") + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:%q`, sink.ComponentKey, "new_append")) +} + +func TestSink_WithEmptyName(t *testing.T) { + s, b := sinkWithBuffer("", 0) + + s.Info(0, "First.") + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:""`, sink.ComponentKey)) + + ss := s.WithName("new") + + ss.Info(0, "Second.") + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:%q`, sink.ComponentKey, "new")) +} + +func TestSink_SetOutput(t *testing.T) { + bb := bytes.NewBuffer(nil) + + s, b := sinkWithBuffer("", 0) + s.SetOutput(bb) + + s.Info(0, "Same or lower than current verbosity. This should be logged.") + require.Empty(t, b.Bytes()) + require.NotEmpty(t, bb.Bytes()) +} + +func TestSink_SetVerbosity(t *testing.T) { + s, b := sinkWithBuffer("", 0) + + s.Info(1, "Above current verbosity. This should not be logged.") + require.Empty(t, b.Bytes()) + + s.SetVerbosity(1) + + s.Info(1, "Same or lower than current verbosity. This should be logged.") + require.NotEmpty(t, b.Bytes()) +} + +func TestSink_GetVerbosity(t *testing.T) { + s, _ := sinkWithBuffer("", 0) + require.Equal(t, 0, s.GetVerbosity()) + + s.SetVerbosity(10) + require.Equal(t, 10, s.GetVerbosity()) +} + +func TestSink_Log_EncodingFailure(t *testing.T) { + unsupportedValues := []float64{ + math.NaN(), + math.Inf(-1), + math.Inf(1), + } + + for _, unsupportedValue := range unsupportedValues { + s, b := sinkWithBuffer("", 0) + + // Info and Error use the same mechanism, so using Info for the test + s.Info(0, "Test unsupported value", "value", unsupportedValue) + msg := string(b.Bytes()) + + require.NotEmpty(t, msg) + require.Contains(t, msg, "failed to encode message") + require.Contains(t, msg, fmt.Sprintf("json: unsupported value: %f", unsupportedValue)) + } +} + +func sinkWithBuffer(component string, level int, keyValuePairs ...interface{}) (*sink.Sink, *bytes.Buffer) { + buffer := bytes.NewBuffer(nil) + sink := sink.NewLogSink(component, buffer, sink.Verbosity(level), sink.JSONEncoder{}, keyValuePairs...) + + return sink, buffer +} diff --git a/log/log.go b/log/log.go index 94aaf07..6966473 100644 --- a/log/log.go +++ b/log/log.go @@ -31,3 +31,15 @@ func NewLoggerWithOptions(component string, opts *Options, keyValuePairs ...inte ), ) } + +// NewLoggerV calls the logr.Logger V() method while updating the internal sink (if possible) +// to be compatible with the new level +func NewLoggerV(logger logr.Logger, level int) logr.Logger { + s, ok := logger.GetSink().(*sink.Sink) + + if ok { + s.SetVerbosity(s.GetVerbosity() + level) + } + + return logger.V(level) +} diff --git a/log/log_test.go b/log/log_test.go index 7f73fa5..5a986a9 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -46,3 +46,13 @@ func TestNewLogger_WithOptions(t *testing.T) { require.Contains(t, msg, componentValue) require.Contains(t, msg, levelValue) } + +func TestNewLoggerV(t *testing.T) { + l := log.NewLogger("mycomponent") + + ll := l.V(1) + require.False(t, ll.Enabled()) + + lv := log.NewLoggerV(l, 1) + require.True(t, lv.Enabled()) +}