Color output on console (#34)

* Color output on console

* fix the tests, change text format to escape value but not key, same in color mode

* add screenshot/example

* add json and makefile showing both json vs color with same sample binary

* update text and screenshot

* add color tests

* update depguard + lint fix

* compactify

* fancier attribute key value output

* update test too

* add comments for exposed functions

.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

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

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:
+
+<!-- run make screenshot and capture screen area to update this -->
+![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)

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 ")
+}

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")
+}

logger.go

@@ -55,20 +55,27 @@ 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:      "> ",
 		LogFileAndLine: true,
 		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 {

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)
 	}