diff --git a/.gitignore b/.gitignore index 6c3cdf3..fdd9bd7 100644 --- a/.gitignore +++ b/.gitignore @@ -1 +1,6 @@ +.DS_Store .golangci.yml +fullsize +smallsize +coverage.out +coverage?.out diff --git a/.vscode/launch.json b/.vscode/launch.json new file mode 100644 index 0000000..a75431d --- /dev/null +++ b/.vscode/launch.json @@ -0,0 +1,14 @@ +{ + "version": "0.2.0", + "configurations": [ + { + "name": "Launch test function with tags", + "type": "go", + "request": "launch", + "mode": "test", + "program": "${workspaceFolder}", + "buildFlags": "-tags=no_json" + } + + ] +} diff --git a/Makefile b/Makefile index 7affc5c..517602e 100644 --- a/Makefile +++ b/Makefile @@ -1,14 +1,35 @@ -all: test example +GO_BIN?=GOTOOLCHAIN=local go + +all: info test lint size-check coverage example + +info: + @echo "### Go (using GO_BIN=\"$(GO_BIN)\") version:" + $(GO_BIN) version test: - go test . -race ./... + $(GO_BIN) test -race ./... + $(GO_BIN) test -tags no_json ./... + $(GO_BIN) test -tags no_http ./... + +local-coverage: coverage + $(GO_BIN) test -coverprofile=coverage.out ./... + $(GO_BIN) tool cover -html=coverage.out + +coverage: + $(GO_BIN) test -coverprofile=coverage1.out ./... + $(GO_BIN) test -tags no_net -coverprofile=coverage2.out ./... + $(GO_BIN) test -tags no_json -coverprofile=coverage3.out ./... + $(GO_BIN) test -tags no_http,no_json -coverprofile=coverage4.out ./... + # cat coverage*.out > coverage.out + $(GO_BIN) install github.com/wadey/gocovmerge@b5bfa59ec0adc420475f97f89b58045c721d761c + gocovmerge coverage?.out > coverage.out example: @echo "### Colorized (default) ###" - go run ./levelsDemo + $(GO_BIN) run ./levelsDemo @echo "### JSON: (redirected stderr) ###" - go run ./levelsDemo 3>&1 1>&2 2>&3 | jq -c + $(GO_BIN) run ./levelsDemo 3>&1 1>&2 2>&3 | jq -c line: @echo @@ -17,12 +38,23 @@ line: screenshot: line example @echo +size-check: + @echo "### Size of the binary:" + CGO_ENABLED=0 $(GO_BIN) build -ldflags="-w -s" -trimpath -o ./fullsize ./levelsDemo + ls -lh ./fullsize + CGO_ENABLED=0 $(GO_BIN) build -tags no_net -ldflags="-w -s" -trimpath -o ./smallsize ./levelsDemo + ls -lh ./smallsize + CGO_ENABLED=0 $(GO_BIN) build -tags no_http,no_json -ldflags="-w -s" -trimpath -o ./smallsize ./levelsDemo + ls -lh ./smallsize + gsa ./smallsize # go install github.com/Zxilly/go-size-analyzer/cmd/gsa@master + lint: .golangci.yml golangci-lint run + golangci-lint run --build-tags no_json .golangci.yml: Makefile curl -fsS -o .golangci.yml https://raw.githubusercontent.com/fortio/workflows/main/golangci.yml -.PHONY: all test example screenshot line lint +.PHONY: all info test lint size-check local-coverage example screenshot line coverage diff --git a/README.md b/README.md index e78028f..51ef7aa 100644 --- a/README.md +++ b/README.md @@ -34,7 +34,7 @@ log.S(log.Info, "msg", log.Attr("key1", value1)...) See the `Config` object for options like whether to include line number and file name of caller or not etc -New since 1.4 server logging (as used in [fortio.org/scli](https://pkg.go.dev/fortio.org/scli#ServerMain) for instance) is now structured (json), client logging (as setup by [fortio.org/cli](https://pkg.go.dev/fortio.org/scli#ServerMain) remains as before. +New since 1.4 server logging (as used in [fortio.org/scli](https://pkg.go.dev/fortio.org/scli#ServerMain) for instance) is now structured (JSON), client logging (as setup by [fortio.org/cli](https://pkg.go.dev/fortio.org/scli#ServerMain) remains as before. One can also revert server to not be JSON through config. @@ -46,7 +46,7 @@ Which can be converted to JSONEntry but is also a fixed, optimized format (ie ts The timestamp `ts` is in seconds.microseconds since epoch (golang UnixMicro() split into seconds part before decimal and microseconds after) -Since 1.8 the Go Routine ID is present in json (`r` field) or colorized log output (for multi threaded server types). +Since 1.8 the Go Routine ID is present in JSON (`r` field) or colorized log output (for multi threaded server types). Optional additional `KeyValue` pairs can be added to the base structure using the new `log.S` or passed to `log.LogRequest` using `log.Any` and `log.Str`. Note that numbers, as well as arrays of any type and maps of string keys to any type are supported (but more expensive to serialize recursively). @@ -63,7 +63,7 @@ When output is redirected, JSON output: {"ts":1689986143.4634,"level":"err","r":1,"file":"levels.go","line":23,"msg":"This is an error message"} {"ts":1689986143.463403,"level":"crit","r":1,"file":"levels.go","line":24,"msg":"This is a critical message"} {"ts":1689986143.463406,"level":"fatal","r":1,"file":"levels.go","line":25,"msg":"This is a fatal message"} -This is a non json output, will get prefixed with a exclamation point with logc +This is a non-JSON output, will get prefixed with a exclamation point with logc ``` When on console: @@ -100,3 +100,11 @@ LOGGER_GOROUTINE_ID=false LOGGER_COMBINE_REQUEST_AND_RESPONSE=true LOGGER_LEVEL='Info' ``` + +# Small binaries + +If you're never logging http requests/responses, use `-tags no_http` (or `-tags no_net`) to exclude the http/https logging utilities (which pulls in a lot of dependencies because of `net/http` init). + +If you never need to JSON log complex structures/types that have a special `json.Marshaler` then you can use `-tags no_net,no_json` for the smallest executables + +(see `make size-check`) diff --git a/codecov.yml b/codecov.yml new file mode 100644 index 0000000..c1f00ca --- /dev/null +++ b/codecov.yml @@ -0,0 +1,6 @@ +coverage: + ignore: + - "levelsDemo" +# not used (is nothing at all used?) +# files: +# - "coverage*.out" diff --git a/http_logging.go b/http_logging.go index 0782c10..503b6fc 100644 --- a/http_logging.go +++ b/http_logging.go @@ -12,6 +12,9 @@ // See the License for the specific language governing permissions and // limitations under the License. +//go:build !no_http && !no_net +// +build !no_http,!no_net + package log import ( diff --git a/http_logging_test.go b/http_logging_test.go index 750d5e1..a9697ee 100644 --- a/http_logging_test.go +++ b/http_logging_test.go @@ -1,3 +1,6 @@ +//go:build !no_http && !no_net +// +build !no_http,!no_net + package log // import "fortio.org/fortio/log" import ( diff --git a/json_logging.go b/json_logging.go new file mode 100644 index 0000000..dad0e56 --- /dev/null +++ b/json_logging.go @@ -0,0 +1,67 @@ +// Copyright 2017-2024 Fortio Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +// Moved json logging out so it can be skipped for smallest binaries based on build tags. +// only difference is with nested struct/array logging or logging of types with json Marchaller interface. + +//go:build !no_json + +package log // import "fortio.org/log" + +import ( + "encoding/json" + "fmt" + "strconv" +) + +var fullJSON = true + +func toJSON(v any) string { + bytes, err := json.Marshal(v) + if err != nil { + return strconv.Quote(fmt.Sprintf("ERR marshaling %v: %v", v, err)) + } + str := string(bytes) + // We now handle errors before calling toJSON: if there is a marshaller we use it + // otherwise we use the string from .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) { + case bool, int, int8, int16, int32, int64, uint, uint8, uint16, uint32, uint64, + float32, float64: + return fmt.Sprint(s) + case string: + return fmt.Sprintf("%q", s) + case error: + // Sadly structured errors like nettwork error don't have the reason in + // the exposed struct/JSON - ie on gets + // {"Op":"read","Net":"tcp","Source":{"IP":"127.0.0.1","Port":60067,"Zone":""}, + // "Addr":{"IP":"127.0.0.1","Port":3000,"Zone":""},"Err":{}} + // instead of + // read tcp 127.0.0.1:60067->127.0.0.1:3000: i/o timeout + // Noticed in https://github.com/fortio/fortio/issues/913 + _, hasMarshaller := s.(json.Marshaler) + if hasMarshaller { + return toJSON(v.Val) + } else { + return fmt.Sprintf("%q", s.Error()) + } + /* 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)) + } +} diff --git a/json_logging_test.go b/json_logging_test.go new file mode 100644 index 0000000..659aed9 --- /dev/null +++ b/json_logging_test.go @@ -0,0 +1,20 @@ +//go:build !no_json +// +build !no_json + +package log // import "fortio.org/fortio/log" + +import ( + "fmt" + "testing" +) + +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) + } +} diff --git a/levelsDemo/levels.go b/levelsDemo/levels.go index 7ec8737..5ef98d0 100644 --- a/levelsDemo/levels.go +++ b/levelsDemo/levels.go @@ -14,10 +14,10 @@ func main() { log.Config.GoroutineID = false log.Debugf("This is a debug message without goroutine id, file:line nor prefix (cli style)") log.Config = log.DefaultConfig() - // So log fatal doesn't panic nor exit (so we can print the non json last line). + // So log fatal doesn't panic nor exit (so we can print the non-JSON last line). log.Config.FatalPanics = false log.Config.FatalExit = func(int) {} - // Meat of the example: (some of these are reproducing fixed issues in `logc` json->console attributes detection) + // Meat of the example: (some of these are reproducing fixed issues in `logc` JSON->console attributes detection) log.Debugf("Back to default (server) logging style with a debug message ending with backslash \\") log.LogVf("This is a verbose message") log.Printf("This an always printed, file:line omitted message (and no level in console)") @@ -28,5 +28,5 @@ func main() { log.Errf("This is an error message") log.Critf("This is a critical message") log.Fatalf("This is a fatal message") //nolint:revive // we disabled exit for this demo - fmt.Println("This is a non json output, will get prefixed with a exclamation point with logc") + fmt.Println("This is a non-JSON output, will get prefixed with a exclamation point with logc") } diff --git a/logger.go b/logger.go index 2fcb8f5..6db46df 100644 --- a/logger.go +++ b/logger.go @@ -25,7 +25,6 @@ package log // import "fortio.org/log" import ( "bytes" - "encoding/json" "flag" "fmt" "io" @@ -349,7 +348,7 @@ func Logf(lvl Level, format string, rest ...interface{}) { logPrintf(lvl, format, rest...) } -// Used when doing our own logging writing, in JSON/structured mode. +// Used when doing our own logging writing, in JSON/structured mode (and some color variants as well, misnomer). var ( jWriter = jsonWriter{w: os.Stderr, tsBuf: make([]byte, 0, 32)} ) @@ -617,6 +616,11 @@ func Bool(key string, value bool) KeyVal { return Any(key, value) } +func Rune(key string, value rune) KeyVal { + // Special case otherwise rune is printed as int32 number + return Any(key, string(value)) // similar to "%c". +} + func (v *KeyVal) StringValue() string { if !v.Cached { v.StrValue = v.Value.String() @@ -631,45 +635,6 @@ type ValueType[T ValueTypes] struct { Val T } -func toJSON(v any) string { - bytes, err := json.Marshal(v) - if err != nil { - return strconv.Quote(fmt.Sprintf("ERR marshaling %v: %v", v, err)) - } - str := string(bytes) - // We now handle errors before calling toJSON: if there is a marshaller we use it - // otherwise we use the string from .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) { - case bool, int, int8, int16, int32, int64, uint, uint8, uint16, uint32, uint64, - float32, float64: - return fmt.Sprint(s) - case string: - return fmt.Sprintf("%q", s) - case error: - // Sadly structured errors like nettwork error don't have the reason in - // the exposed struct/JSON - ie on gets - // {"Op":"read","Net":"tcp","Source":{"IP":"127.0.0.1","Port":60067,"Zone":""}, - // "Addr":{"IP":"127.0.0.1","Port":3000,"Zone":""},"Err":{}} - // instead of - // read tcp 127.0.0.1:60067->127.0.0.1:3000: i/o timeout - // Noticed in https://github.com/fortio/fortio/issues/913 - _, hasMarshaller := s.(json.Marshaler) - if hasMarshaller { - return toJSON(v.Val) - } else { - return fmt.Sprintf("%q", s.Error()) - } - /* 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)) - } -} - // Our original name, now switched to slog style Any. func Attr[T ValueTypes](key string, value T) KeyVal { return Any(key, value) diff --git a/logger_test.go b/logger_test.go index d7c175e..ef966c4 100644 --- a/logger_test.go +++ b/logger_test.go @@ -767,6 +767,90 @@ func (e customError) MarshalJSON() ([]byte, error) { return json.Marshal(customErrorAlias(e)) } +func TestPointers(t *testing.T) { + var iPtr *int + kv := Any("err", iPtr) + kvStr := kv.StringValue() + expected := `null` + if kvStr != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", kvStr, expected) + } + i := 42 + iPtr = &i + kv = Any("int", iPtr) + kvStr = kv.StringValue() + expected = `42` + if kvStr != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", kvStr, expected) + } + var sPtr *string + kv = Any("msg", sPtr) + kvStr = kv.StringValue() + expected = `null` + if kvStr != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", kvStr, expected) + } + s := "test\nline2" + sPtr = &s + kv = Any("msg", sPtr) + kvStr = kv.StringValue() + expected = `"test\nline2"` + if kvStr != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", kvStr, expected) + } +} + +func TestMoreTypes(t *testing.T) { + var b byte = 42 + kv := Any("byte", b) + kvStr := kv.StringValue() + expected := `42` + if kvStr != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", kvStr, expected) + } + runes := []rune(`A"Φ`) // test plain ascii, a double quote, and multibyte + r := runes[0] + kv = Rune("rune", r) + kvStr = kv.StringValue() + expected = `"A"` + if kvStr != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", kvStr, expected) + } + r = runes[1] + kv = Rune("rune", r) + kvStr = kv.StringValue() + expected = `"\""` + if kvStr != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", kvStr, expected) + } + r = runes[2] + kv = Rune("rune", r) + kvStr = kv.StringValue() + expected = `"Φ"` + if kvStr != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", kvStr, expected) + } +} + +func TestStruct(t *testing.T) { + type testStruct struct { + Msg1 string + Msg2 *string + } + ptrStr := "test2" + ts := testStruct{Msg1: "test\nline2", Msg2: &ptrStr} + kv := Any("ts", ts) + kvStr := kv.StringValue() + expected := `{"Msg1":"test\nline2","Msg2":"test2"}` + if !fullJSON { + expected = `"{Msg1:test\nline2 Msg2:` + expected += fmt.Sprintf("%p}\"", &ptrStr) + } + if kvStr != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", kvStr, expected) + } +} + func TestSerializationOfError(t *testing.T) { var err error kv := Any("err", err) @@ -788,22 +872,14 @@ func TestSerializationOfError(t *testing.T) { kv = Any("err", err) kvStr = kv.StringValue() expected = `{"Msg":"custom error","Code":42}` + if !fullJSON { + expected = `"custom error custom error (code 42)"` + } if kvStr != expected { t.Errorf("unexpected:\n%s\nvs:\n%s\n", kvStr, expected) } } -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) - } -} - func TestEnvHelp(t *testing.T) { SetDefaultsForClientTools() Config.NoTimestamp = false diff --git a/no_json_logging.go b/no_json_logging.go new file mode 100644 index 0000000..7128875 --- /dev/null +++ b/no_json_logging.go @@ -0,0 +1,103 @@ +// Copyright 2017-2024 Fortio Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +// Moved JSON logging out so it can be skipped for smallest binaries based on build tags. +// This file is the variant that does serialization manually instead of using json.Marshal. + +//go:build no_json + +package log // import "fortio.org/log" + +import ( + "fmt" + "reflect" + "sort" + "strings" +) + +var fullJSON = false + +// restore version "manual json serialization" from +// https://github.com/fortio/log/pull/46/files#diff-ff87b7c4777a35588053a509583d66c9f404ccbea9e1c71d2a5f224d7ad1323e +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() +} + +const nullString = "null" + +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) { + case bool, int, int8, int16, int32, int64, uint, uint8, uint16, uint32, uint64, + float32, float64: + return fmt.Sprint(s) + case string: + return fmt.Sprintf("%q", s) + case *string: + if s == nil { + return nullString + } + return fmt.Sprintf("%q", *s) + case []interface{}: + return arrayToString(s) + case map[string]interface{}: + return mapToString(s) + case error: + return fmt.Sprintf("%q", s.Error()) // nil errors handled in case nil below + case nil: + return nullString // nil interface{} like `var err error` (but not nil *string etc.) + default: + val := reflect.ValueOf(s) + k := val.Kind() + if k == reflect.Ptr || k == reflect.Interface { + if val.IsNil() { + return nullString + } + vv := ValueType[interface{}]{Val: val.Elem().Interface()} + return vv.String() + } + return fmt.Sprintf("%q", fmt.Sprintf("%+v", v.Val)) + } +}