Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Color output on console #34

Merged
merged 12 commits into from
Jul 6, 2023
7 changes: 6 additions & 1 deletion .golangci.yml
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
20 changes: 20 additions & 0 deletions Makefile
Original file line number Diff line number Diff line change
@@ -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
23 changes: 21 additions & 2 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Binary file added color.png
Loading
Sorry, something went wrong. Reload?
Sorry, we cannot display this file.
Sorry, this file is invalid so it cannot be displayed.
80 changes: 80 additions & 0 deletions console_logging.go
Original file line number Diff line number Diff line change
@@ -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 ")
}
27 changes: 27 additions & 0 deletions levelsDemo/levels.go
Original file line number Diff line number Diff line change
@@ -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")
}
42 changes: 34 additions & 8 deletions logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -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,
}
}

Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -146,6 +155,7 @@ func init() {
levelToStrM[strings.ToLower(name)] = Level(l)
}
log.SetFlags(log.Ltime)
SetColorMode()
}

func setLevel(lvl Level) {
Expand Down Expand Up @@ -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 {
Expand All @@ -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.
Expand Down Expand Up @@ -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 {
Expand Down
50 changes: 46 additions & 4 deletions logger_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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")
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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)
}
Expand Down