From 670bfc6970a474a3b3384f1fe466a1a078a4bbfd Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Sat, 21 Oct 2023 17:55:40 -0700 Subject: [PATCH 1/6] recursive json serialization for Any --- http_logging_test.go | 4 ++-- logger.go | 18 +++++++++++++++--- 2 files changed, 17 insertions(+), 5 deletions(-) diff --git a/http_logging_test.go b/http_logging_test.go index 09558ab..e7785be 100644 --- a/http_logging_test.go +++ b/http_logging_test.go @@ -30,8 +30,8 @@ func TestLogRequest(t *testing.T) { w.Flush() actual := b.String() //nolint: lll - expected := `{"level":"info","msg":"test1","method":"","url":"","proto":"","remote_addr":"","host":"foo-host:123","header.x-forwarded-proto":"","header.x-forwarded-for":"","user-agent":"","tls":true,"tls.peer_cn":"x\nyz","header.foo":"bar1,bar2"} -{"level":"info","msg":"test2","method":"","url":"","proto":"","remote_addr":"","host":"foo-host:123","header.x-forwarded-proto":"","header.x-forwarded-for":"","user-agent":"","extra1":"v1","extra2":"v2"} + expected := `{"level":"info","msg":"test1","method":"","url":null,"proto":"","remote_addr":"","host":"foo-host:123","header.x-forwarded-proto":"","header.x-forwarded-for":"","user-agent":"","tls":true,"tls.peer_cn":"x\nyz","header.foo":"bar1,bar2"} +{"level":"info","msg":"test2","method":"","url":null,"proto":"","remote_addr":"","host":"foo-host:123","header.x-forwarded-proto":"","header.x-forwarded-for":"","user-agent":"","extra1":"v1","extra2":"v2"} ` if actual != expected { t.Errorf("unexpected:\n%s\nvs:\n%s\n", actual, expected) diff --git a/logger.go b/logger.go index 5499121..2783f67 100644 --- a/logger.go +++ b/logger.go @@ -25,6 +25,7 @@ package log // import "fortio.org/log" import ( "bytes" + "encoding/json" "flag" "fmt" "io" @@ -32,7 +33,6 @@ import ( "math" "os" "runtime" - "sort" "strconv" "strings" "sync" @@ -589,6 +589,7 @@ type ValueType[T ValueTypes] struct { Val T } +/* func arrayToString(s []interface{}) string { var buf strings.Builder buf.WriteString("[") @@ -623,19 +624,30 @@ func mapToString(s map[string]interface{}) string { buf.WriteString("}") return buf.String() } +*/ + +func toJSON[T ValueTypes](v T) string { + bytes, err := json.Marshal(v) + if err != nil { + return fmt.Sprintf("ERR marshaling %v: %v", v, err) + } + return string(bytes) +} func (v ValueType[T]) String() string { // if the type is numeric, use Sprint(v.val) otherwise use Sprintf("%q", v.Val) to quote it. - switch s := any(v.Val).(type) { + switch /*s :=*/ any(v.Val).(type) { case bool, int, int8, int16, int32, int64, uint, uint8, uint16, uint32, uint64, float32, float64: return fmt.Sprint(v.Val) + /* It's all handled by json fallback now - todo test if this is/was cheaper? case []interface{}: return arrayToString(s) case map[string]interface{}: return mapToString(s) + */ default: - return fmt.Sprintf("%q", fmt.Sprint(v.Val)) + return toJSON(v.Val) // was fmt.Sprintf("%q", fmt.Sprint(v.Val)) } } From df6a20102f020e08bf3ed4ea2e9f31b8e4853f91 Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Wed, 15 Nov 2023 19:34:22 -0800 Subject: [PATCH 2/6] fix the special case for error / empty string --- logger.go | 4 +++- logger_test.go | 12 ++++++++++++ 2 files changed, 15 insertions(+), 1 deletion(-) diff --git a/logger.go b/logger.go index 2783f67..dd1d639 100644 --- a/logger.go +++ b/logger.go @@ -636,10 +636,12 @@ func toJSON[T ValueTypes](v T) string { func (v ValueType[T]) String() string { // if the type is numeric, use Sprint(v.val) otherwise use Sprintf("%q", v.Val) to quote it. - switch /*s :=*/ any(v.Val).(type) { + switch s := any(v.Val).(type) { case bool, int, int8, int16, int32, int64, uint, uint8, uint16, uint32, uint64, float32, float64: return fmt.Sprint(v.Val) + case error: // struct with no public fields so we need to call Error() to get a string. otherwise we get {} + return fmt.Sprintf("%q", s.Error()) /* It's all handled by json fallback now - todo test if this is/was cheaper? case []interface{}: return arrayToString(s) diff --git a/logger_test.go b/logger_test.go index ed5b5db..bc82299 100644 --- a/logger_test.go +++ b/logger_test.go @@ -752,6 +752,18 @@ func TestNoLevel(t *testing.T) { } } +func TestSerializationOfError(t *testing.T) { + err := fmt.Errorf("test error") + Errf("Error on purpose: %v", err) + S(Error, "Error on purpose", Any("err", err)) + kv := Any("err", err) + kvStr := kv.StringValue() + expected := `"test error"` + if kvStr != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", kvStr, expected) + } +} + // io.Discard but specially known to by logger optimizations for instance. type discard struct{} From 4cb8e0dcebe2e4c216c394929ff7629efe4fbdca Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Wed, 15 Nov 2023 20:39:01 -0800 Subject: [PATCH 3/6] refine error type treatment to allow custom serialization if it exists/there are public fields --- logger.go | 21 +++++++++++++++++---- logger_test.go | 31 +++++++++++++++++++++++++++---- 2 files changed, 44 insertions(+), 8 deletions(-) diff --git a/logger.go b/logger.go index dd1d639..d2be5cf 100644 --- a/logger.go +++ b/logger.go @@ -626,23 +626,36 @@ func mapToString(s map[string]interface{}) string { } */ -func toJSON[T ValueTypes](v T) string { +func toJSON(v any) string { + e, isError := v.(error) // Remember and cast only once if this is an error type or not + if isError { + // Check for nil explicitly if v is an error + if e == nil { + return "null" + } + } bytes, err := json.Marshal(v) if err != nil { return fmt.Sprintf("ERR marshaling %v: %v", v, err) } - return string(bytes) + str := string(bytes) + // This is kinda hacky way to handle both structured and custom serialization errors, and + // struct with no public fields for which we need to call Error() to get a useful string. + if isError && str == "{}" { + return fmt.Sprintf("%q", e.Error()) + } + return str } func (v ValueType[T]) String() string { // if the type is numeric, use Sprint(v.val) otherwise use Sprintf("%q", v.Val) to quote it. - switch s := any(v.Val).(type) { + switch /*s :=*/ any(v.Val).(type) { case bool, int, int8, int16, int32, int64, uint, uint8, uint16, uint32, uint64, float32, float64: return fmt.Sprint(v.Val) + /* It's all handled by json fallback now - todo test if this is/was cheaper? case error: // struct with no public fields so we need to call Error() to get a string. otherwise we get {} return fmt.Sprintf("%q", s.Error()) - /* It's all handled by json fallback now - todo test if this is/was cheaper? case []interface{}: return arrayToString(s) case map[string]interface{}: diff --git a/logger_test.go b/logger_test.go index bc82299..3479cc3 100644 --- a/logger_test.go +++ b/logger_test.go @@ -752,13 +752,36 @@ func TestNoLevel(t *testing.T) { } } +type customError struct { + Msg string + Code int +} + +func (e customError) Error() string { + return fmt.Sprintf("custom error %s (code %d)", e.Msg, e.Code) +} + func TestSerializationOfError(t *testing.T) { - err := fmt.Errorf("test error") - Errf("Error on purpose: %v", err) - S(Error, "Error on purpose", Any("err", err)) + var err error kv := Any("err", err) kvStr := kv.StringValue() - expected := `"test error"` + expected := `null` + if kvStr != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", kvStr, expected) + } + err = fmt.Errorf("test error") + Errf("Error on purpose: %v", err) + S(Error, "Error on purpose", Any("err", err)) + kv = Any("err", err) + kvStr = kv.StringValue() + expected = `"test error"` + if kvStr != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", kvStr, expected) + } + err = customError{Msg: "custom error", Code: 42} + kv = Any("err", err) + kvStr = kv.StringValue() + expected = `{"Msg":"custom error","Code":42}` if kvStr != expected { t.Errorf("unexpected:\n%s\nvs:\n%s\n", kvStr, expected) } From d0f1deee4e9e6ad5670ca19ead5677e31972d4db Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Wed, 15 Nov 2023 20:58:15 -0800 Subject: [PATCH 4/6] remove dead code/never triggering nil check --- logger.go | 9 +-------- 1 file changed, 1 insertion(+), 8 deletions(-) diff --git a/logger.go b/logger.go index d2be5cf..6878a48 100644 --- a/logger.go +++ b/logger.go @@ -627,13 +627,6 @@ func mapToString(s map[string]interface{}) string { */ func toJSON(v any) string { - e, isError := v.(error) // Remember and cast only once if this is an error type or not - if isError { - // Check for nil explicitly if v is an error - if e == nil { - return "null" - } - } bytes, err := json.Marshal(v) if err != nil { return fmt.Sprintf("ERR marshaling %v: %v", v, err) @@ -641,7 +634,7 @@ func toJSON(v any) string { str := string(bytes) // This is kinda hacky way to handle both structured and custom serialization errors, and // struct with no public fields for which we need to call Error() to get a useful string. - if isError && str == "{}" { + if e, isError := v.(error); isError && str == "{}" { return fmt.Sprintf("%q", e.Error()) } return str From 581f043760db9deef38e825d47ba735d3fc8a72e Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Mon, 20 Nov 2023 12:37:56 -0800 Subject: [PATCH 5/6] remove dead code, not called anyway for things like []int --- logger.go | 52 +++++----------------------------------------------- 1 file changed, 5 insertions(+), 47 deletions(-) diff --git a/logger.go b/logger.go index 6878a48..eba4e9e 100644 --- a/logger.go +++ b/logger.go @@ -589,43 +589,6 @@ type ValueType[T ValueTypes] struct { Val T } -/* -func arrayToString(s []interface{}) string { - var buf strings.Builder - buf.WriteString("[") - for i, e := range s { - if i != 0 { - buf.WriteString(",") - } - vv := ValueType[interface{}]{Val: e} - buf.WriteString(vv.String()) - } - buf.WriteString("]") - return buf.String() -} - -func mapToString(s map[string]interface{}) string { - var buf strings.Builder - buf.WriteString("{") - keys := make([]string, 0, len(s)) - for k := range s { - keys = append(keys, k) - } - sort.Strings(keys) - for i, k := range keys { - if i != 0 { - buf.WriteString(",") - } - buf.WriteString(fmt.Sprintf("%q", k)) - buf.WriteString(":") - vv := ValueType[interface{}]{Val: s[k]} - buf.WriteString(vv.String()) - } - buf.WriteString("}") - return buf.String() -} -*/ - func toJSON(v any) string { bytes, err := json.Marshal(v) if err != nil { @@ -642,18 +605,13 @@ func toJSON(v any) string { func (v ValueType[T]) String() string { // if the type is numeric, use Sprint(v.val) otherwise use Sprintf("%q", v.Val) to quote it. - switch /*s :=*/ any(v.Val).(type) { + switch s := any(v.Val).(type) { case bool, int, int8, int16, int32, int64, uint, uint8, uint16, uint32, uint64, float32, float64: - return fmt.Sprint(v.Val) - /* It's all handled by json fallback now - todo test if this is/was cheaper? - case error: // struct with no public fields so we need to call Error() to get a string. otherwise we get {} - return fmt.Sprintf("%q", s.Error()) - case []interface{}: - return arrayToString(s) - case map[string]interface{}: - return mapToString(s) - */ + return fmt.Sprint(s) + case string: + return fmt.Sprintf("%q", s) + /* It's all handled by json fallback now even though slightly more expensive at runtime, it's a lot simpler */ default: return toJSON(v.Val) // was fmt.Sprintf("%q", fmt.Sprint(v.Val)) } From ac8c6896f0feb3064e40bc956fc129ecbff935cc Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Mon, 20 Nov 2023 14:15:55 -0800 Subject: [PATCH 6/6] ensure the result will be a valid json string even in the error case, test the error case --- logger.go | 2 +- logger_test.go | 11 +++++++++++ 2 files changed, 12 insertions(+), 1 deletion(-) diff --git a/logger.go b/logger.go index eba4e9e..c80c13e 100644 --- a/logger.go +++ b/logger.go @@ -592,7 +592,7 @@ type ValueType[T ValueTypes] struct { func toJSON(v any) string { bytes, err := json.Marshal(v) if err != nil { - return fmt.Sprintf("ERR marshaling %v: %v", v, err) + return strconv.Quote(fmt.Sprintf("ERR marshaling %v: %v", v, err)) } str := string(bytes) // This is kinda hacky way to handle both structured and custom serialization errors, and diff --git a/logger_test.go b/logger_test.go index 3479cc3..cf24fe1 100644 --- a/logger_test.go +++ b/logger_test.go @@ -787,6 +787,17 @@ func TestSerializationOfError(t *testing.T) { } } +func TestToJSON_MarshalError(t *testing.T) { + badValue := make(chan int) + + expected := fmt.Sprintf("\"ERR marshaling %v: %v\"", badValue, "json: unsupported type: chan int") + actual := toJSON(badValue) + + if actual != expected { + t.Errorf("Expected %q, got %q", expected, actual) + } +} + // io.Discard but specially known to by logger optimizations for instance. type discard struct{}