diff --git a/.golangci.yml b/.golangci.yml index f670088..2aefbf3 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -46,7 +46,12 @@ linters-settings: enable-all: true disable-all: false depguard: - # new depguard default is to complain for anything not std package which works for this specific base package + rules: + main: + # List of allowed packages. + allow: + - $gostd + - fortio.org/log lll: # max line length, lines longer will be reported. Default is 120. # '\t' is counted as 1 character by default, and can be changed with the tab-width option diff --git a/Makefile b/Makefile new file mode 100644 index 0000000..917a10e --- /dev/null +++ b/Makefile @@ -0,0 +1,20 @@ + +all: test example + +test: + go test . -race ./... + +example: + @echo "### Colorized (default) ###" + go run ./levelsDemo + @echo "### JSON: (redirected stderr) ###" + go run ./levelsDemo 3>&1 1>&2 2>&3 | jq -c + +line: + @echo + +# Suitable to make a screenshot with a bit of spaces around for updating color.png +screenshot: line example + @echo + +.PHONY: all test example screenshot line diff --git a/README.md b/README.md index b314431..555d174 100644 --- a/README.md +++ b/README.md @@ -48,6 +48,25 @@ The timestamp `ts` is in microseconds since epoch (golang UnixMicro()) Optional additional `KeyValue` pairs can be added to the base structure using the new `log.S` or passed to `log.LogRequest` using `log.Attr` and `log.Str`. -JSON formatted logs can be converted back to text and colorized using [fortio.org/logc](https://github.com/fortio/logc#logc) +If console output is detected (and ConsoleColor is true, which is the default) or if ForceColor is set, colorized output similar to `logc` will be done instead of JSON. [levelsDemo/levels.go](levelsDemo/levels.go) produces the following output: -![Example console color output](https://github.com/fortio/logc/raw/main/example.png) +When output is redirected, JSON output: +```json +{"ts":1688674146.025678,"level":"dbug","file":"levels.go","line":15,"msg":"This is a debug message ending with backslash"} +{"ts":1688674146.025708,"level":"trace","file":"levels.go","line":16,"msg":"This is a verbose message"} +{"ts":1688674146.025714,"level":"info","msg":"This an always printed, file:line omitted message"} +{"ts":1688674146.025717,"level":"info","file":"levels.go","line":18,"msg":"This is an info message with no attributes but with \"quotes\"..."} +{"ts":1688674146.025735,"level":"info","file":"levels.go","line":19,"msg":"This is multi line\n\tstructured info message with 3 attributes","attr1":"value1","attr2":"42","attr3":"\"quoted\nvalue\""} +{"ts":1688674146.025741,"level":"warn","file":"levels.go","line":21,"msg":"This is a warning message"} +{"ts":1688674146.025743,"level":"err","file":"levels.go","line":22,"msg":"This is an error message"} +{"ts":1688674146.025745,"level":"crit","file":"levels.go","line":23,"msg":"This is a critical message"} +{"ts":1688674146.025748,"level":"fatal","file":"levels.go","line":24,"msg":"This is a fatal message"} +This is stdout normal output +``` + +When on console: + + +![Example console color output](color.png) + +JSON formatted logs can also be converted back to text later/after capture and similarly colorized using [fortio.org/logc](https://github.com/fortio/logc#logc) diff --git a/color.png b/color.png new file mode 100644 index 0000000..658e42d Binary files /dev/null and b/color.png differ diff --git a/console_logging.go b/console_logging.go new file mode 100644 index 0000000..5727546 --- /dev/null +++ b/console_logging.go @@ -0,0 +1,80 @@ +// Copyright 2023 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. + +package log + +import ( + "os" + "time" +) + +const ( + // ANSI color codes. + reset = "\033[0m" + red = "\033[31m" + green = "\033[32m" + yellow = "\033[33m" + blue = "\033[34m" + purple = "\033[35m" + cyan = "\033[36m" + gray = "\033[37m" + white = "\033[97m" + brightRed = "\033[91m" + darkGray = "\033[90m" +) + +var ( + // Mapping of log levels to color. + LevelToColor = []string{ + gray, + cyan, + green, + yellow, + red, + purple, + brightRed, + } + // Cached flag for whether to use color output or not. + Color = false +) + +// ConsoleLogging is a utility to check if the current logger output is a console (terminal). +func ConsoleLogging() bool { + f, ok := jsonWriter.(*os.File) + if !ok { + return false + } + s, _ := f.Stat() + return (s.Mode() & os.ModeCharDevice) == os.ModeCharDevice +} + +// SetColorMode computes whether we currently should be using color text mode or not. +// Need to be reset if config changes (but is already automatically re evaluated when calling SetOutput()). +func SetColorMode() { + Color = ColorMode() +} + +// ColorMode returns true if we should be using color text mode, which is either because it's +// forced or because we are in a console and the config allows it. +// Should not be called often, instead read/update the Color variable when needed. +func ColorMode() bool { + return Config.ForceColor || (Config.ConsoleColor && ConsoleLogging()) +} + +func colorTimestamp() string { + if Config.NoTimestamp { + return "" + } + return time.Now().Format("\033[90m15:04:05.000 ") +} diff --git a/levelsDemo/levels.go b/levelsDemo/levels.go new file mode 100644 index 0000000..792424b --- /dev/null +++ b/levelsDemo/levels.go @@ -0,0 +1,27 @@ +// Initially from https://github.com/fortio/logc/blob/v1.1.0/levelsDemo/levels.go +package main + +import ( + "fmt" + + "fortio.org/log" +) + +func main() { + // 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) {} + log.SetLogLevelQuiet(log.Debug) + // Meat of the example: (some of these are reproducing fixed issues in `logc` json->console attributes detection) + log.Debugf("This is a debug message ending with backslash \\") + log.LogVf("This is a verbose message") + log.Printf("This an always printed, file:line omitted message") + log.Infof("This is an info message with no attributes but with \"quotes\"...") + log.S(log.Info, "This is multi line\n\tstructured info message with 3 attributes", + log.Str("attr1", "value1"), log.Attr("attr2", 42), log.Str("attr3", "\"quoted\nvalue\"")) + log.Warnf("This is a warning message") + 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") +} diff --git a/logger.go b/logger.go index 9d070c8..f656760 100644 --- a/logger.go +++ b/logger.go @@ -55,13 +55,19 @@ type LogConfig struct { LogFileAndLine bool // Logs filename and line number of callers to log. FatalPanics bool // If true, log.Fatalf will panic (stack trace) instead of just exit 1 FatalExit func(int) // Function to call upon log.Fatalf. e.g. os.Exit. - JSON bool // If true, log in structured JSON format instead of text. + JSON bool // If true, log in structured JSON format instead of text (but see ConsoleColor). NoTimestamp bool // If true, don't log timestamp in json. + ConsoleColor bool // If true and we detect console output (not redirected), use text+color mode. + // Force color mode even if logger output is not console (useful for CI that recognize ansi colors). + // SetColorMode() must be called if this or ConsoleColor are changed. + ForceColor bool } // DefaultConfig() returns the default initial configuration for the logger, best suited // for servers. It will log caller file and line number, use a prefix to split line info // from the message and panic (+exit) on Fatal. +// It's JSON structured by default, unless console is detected. +// Use SetDefaultsForClientTools for CLIs. func DefaultConfig() *LogConfig { return &LogConfig{ LogPrefix: "> ", @@ -69,6 +75,7 @@ func DefaultConfig() *LogConfig { FatalPanics: true, FatalExit: os.Exit, JSON: true, + ConsoleColor: true, } } @@ -108,7 +115,9 @@ func SetDefaultsForClientTools() { Config.LogPrefix = "" Config.LogFileAndLine = false Config.FatalPanics = false + Config.ConsoleColor = true Config.JSON = false + SetColorMode() } // JSONEntry is the logical format of the JSON [Config.JSON] output mode. @@ -146,6 +155,7 @@ func init() { levelToStrM[strings.ToLower(name)] = Level(l) } log.SetFlags(log.Ltime) + SetColorMode() } func setLevel(lvl Level) { @@ -323,14 +333,20 @@ func logUnconditionalf(logFileAndLine bool, lvl Level, format string, rest ...in if logFileAndLine { //nolint:nestif _, file, line, _ := runtime.Caller(3) file = file[strings.LastIndex(file, "/")+1:] - if Config.JSON { + if Color { + jsonWrite(fmt.Sprintf("%s%s%s %s:%d%s%s%s\n", + colorTimestamp(), LevelToColor[lvl], LevelToStrA[lvl][0:1], file, line, Config.LogPrefix, fmt.Sprintf(format, rest...), reset)) + } else if Config.JSON { jsonWrite(fmt.Sprintf("{%s\"level\":%s,\"file\":%q,\"line\":%d,\"msg\":%q}\n", jsonTimestamp(), LevelToJSON[lvl], file, line, fmt.Sprintf(format, rest...))) } else { log.Print(LevelToStrA[lvl][0:1], " ", file, ":", line, Config.LogPrefix, fmt.Sprintf(format, rest...)) } } else { - if Config.JSON { + if Color { + jsonWrite(fmt.Sprintf("%s%s%s %s%s%s\n", + colorTimestamp(), LevelToColor[lvl], LevelToStrA[lvl][0:1], Config.LogPrefix, fmt.Sprintf(format, rest...), reset)) + } else if Config.JSON { jsonWrite(fmt.Sprintf("{%s\"level\":%s,\"msg\":%q}\n", jsonTimestamp(), LevelToJSON[lvl], fmt.Sprintf(format, rest...))) } else { @@ -348,6 +364,7 @@ func Printf(format string, rest ...interface{}) { func SetOutput(w io.Writer) { jsonWriter = w log.SetOutput(w) + SetColorMode() // reset color mode boolean } // SetFlags forwards flags to the system logger. @@ -476,32 +493,41 @@ func Attr[T ValueTypes](key string, value T) KeyVal { } } +// S logs a message of the given level with additional attributes. func S(lvl Level, msg string, attrs ...KeyVal) { if !Log(lvl) { return } buf := strings.Builder{} var format string - if Config.JSON { + if Color { + format = reset + ", " + blue + "%s" + reset + "=" + LevelToColor[lvl] + "%q" + } else if Config.JSON { format = ",%q:%q" } else { - format = ", %s=%s" + format = ", %s=%q" } for _, attr := range attrs { buf.WriteString(fmt.Sprintf(format, attr.Key, attr.Value.String())) } + // TODO share code with log.logUnconditionalf yet without extra locks or allocations/buffers? if Config.LogFileAndLine { //nolint:nestif _, file, line, _ := runtime.Caller(1) file = file[strings.LastIndex(file, "/")+1:] - if Config.JSON { - // TODO share code with log.Printf yet without extra locks or allocations/buffers? + if Color { + jsonWrite(fmt.Sprintf("%s%s%s %s:%d%s%s%s%s\n", + colorTimestamp(), LevelToColor[lvl], LevelToStrA[lvl][0:1], file, line, Config.LogPrefix, msg, buf.String(), reset)) + } else if Config.JSON { jsonWrite(fmt.Sprintf("{%s\"level\":%s,\"file\":%q,\"line\":%d,\"msg\":%q%s}\n", jsonTimestamp(), LevelToJSON[lvl], file, line, msg, buf.String())) } else { log.Print(LevelToStrA[lvl][0:1], " ", file, ":", line, Config.LogPrefix, msg, buf.String()) } } else { - if Config.JSON { + if Color { + jsonWrite(fmt.Sprintf("%s%s%s %s%s%s%s\n", + colorTimestamp(), LevelToColor[lvl], LevelToStrA[lvl][0:1], Config.LogPrefix, msg, buf.String(), reset)) + } else if Config.JSON { jsonWrite(fmt.Sprintf("{%s\"level\":%s,\"msg\":%q%s}\n", jsonTimestamp(), LevelToJSON[lvl], msg, buf.String())) } else { diff --git a/logger_test.go b/logger_test.go index 29d142b..4c47aa6 100644 --- a/logger_test.go +++ b/logger_test.go @@ -102,13 +102,55 @@ func Test_LogS_JSON_no_json_with_filename(t *testing.T) { Printf("This will show too") // no filename/line and shows despite level _ = w.Flush() actual := b.String() - expected := "W logger_test.go:101-bar-This will show, key1=value 1, key2=42\n" + + expected := "W logger_test.go:101-bar-This will show, key1=\"value 1\", key2=\"42\"\n" + "I -bar-This will show too\n" if actual != expected { t.Errorf("got %q expected %q", actual, expected) } } +func TestColorMode(t *testing.T) { + if ConsoleLogging() { + t.Errorf("expected not to be console logging") + } + if Color { + t.Errorf("expected to not be in color mode initially") + } + // Setup + Config = DefaultConfig() + Config.ForceColor = true + Config.NoTimestamp = true + SetLogLevelQuiet(Info) + var b bytes.Buffer + w := bufio.NewWriter(&b) + SetOutput(w) // will call SetColorMode() + if !Color { + t.Errorf("expected to be in color mode after ForceColor=true and SetColorMode()") + } + S(Warning, "With file and line", Str("attr", "value with space")) // line 130 + Infof("info with file and line = %v", Config.LogFileAndLine) // line 131 + Config.LogFileAndLine = false + S(Warning, "Without file and line", Str("attr", "value with space")) + Infof("info with file and line = %v", Config.LogFileAndLine) + _ = w.Flush() + actual := b.String() + expected := "\x1b[33mW logger_test.go:130> With file and line\x1b[0m, \x1b[34mattr\x1b[0m=\x1b[33m\"value with space\"\x1b[0m\n" + + "\x1b[32mI logger_test.go:131> info with file and line = true\x1b[0m\n" + + "\x1b[33mW > Without file and line\x1b[0m, \x1b[34mattr\x1b[0m=\x1b[33m\"value with space\"\x1b[0m\n" + + "\x1b[32mI > info with file and line = false\x1b[0m\n" + if actual != expected { + t.Errorf("got:\n%q\nexpected:\n%q", actual, expected) + } + // See color timestamp + Config.NoTimestamp = false + cs := colorTimestamp() + if cs == "" { + t.Errorf("got empty color timestamp") + } + // Reset for other/further tests + Config.ForceColor = false +} + func TestSetLevel(t *testing.T) { _ = SetLogLevel(Info) err := SetLogLevelStr("debug") @@ -220,7 +262,7 @@ func TestLoggerJSON(t *testing.T) { if e.File != thisFilename { t.Errorf("unexpected file %q", e.File) } - if e.Line < 180 || e.Line > 240 { + if e.Line < 230 || e.Line > 280 { t.Errorf("unexpected line %d", e.Line) } ts := e.Time() @@ -264,7 +306,7 @@ func Test_LogS_JSON(t *testing.T) { if e.File != thisFilename { t.Errorf("unexpected file %q", e.File) } - if e.Line < 230 || e.Line > 300 { + if e.Line < 270 || e.Line > 340 { t.Errorf("unexpected line %d", e.Line) } ts := e.Time() @@ -339,7 +381,7 @@ func Test_LogS_JSON_no_json_no_file(t *testing.T) { S(Warning, "This will show", Str("key1", "value 1"), Attr("key2", 42)) _ = w.Flush() actual := b.String() - expected := "W -foo-This will show, key1=value 1, key2=42\n" + expected := "W -foo-This will show, key1=\"value 1\", key2=\"42\"\n" if actual != expected { t.Errorf("got %q expected %q", actual, expected) }