Merge branch 'iwpnd-feat/json-logs'

cmd/tile38-server/main.go

@@ -10,6 +10,7 @@ import (
 	_ "net/http/pprof"
 	"os"
 	"os/signal"
+	"path/filepath"
 	"runtime"
 	"runtime/pprof"
 	"strconv"
@@ -17,6 +18,7 @@ import (
 	"sync"
 	"syscall"
 
+	"github.com/tidwall/gjson"
 	"github.com/tidwall/tile38/core"
 	"github.com/tidwall/tile38/internal/hservice"
 	"github.com/tidwall/tile38/internal/log"
@@ -76,6 +78,7 @@ Basic Options:
   -p port     : listening port (default: 9851)
   -d path     : data directory (default: data)
   -s socket   : listen on unix socket file
+  -l encoding : set log encoding to json or text (default: text) 
   -q          : no logging. totally silent output
   -v          : enable verbose logging
   -vv         : enable very verbose logging
@@ -88,6 +91,7 @@ Advanced Options:
   --http-transport yes/no : HTTP transport (default: yes)
   --protected-mode yes/no : protected mode (default: yes)
   --nohup                 : do not exit on SIGHUP
+  --logjson               : log json (default: text)
 
 Developer Options:
   --dev                             : enable developer mode
@@ -256,6 +260,7 @@ Developer Options:
 		unixSocket  string
 		verbose     bool
 		veryVerbose bool
+		logEncoding string
 		quiet       bool
 		pidfile     string
 		cpuprofile  string
@@ -268,6 +273,7 @@ Developer Options:
 	flag.StringVar(&host, "h", "", "The listening host")
 	flag.StringVar(&unixSocket, "s", "", "Listen on a unix socket")
 	flag.StringVar(&dir, "d", "data", "The data directory")
+	flag.StringVar(&logEncoding, "l", "text", "The log encoding json or text (default: text)")
 	flag.BoolVar(&verbose, "v", false, "Enable verbose logging")
 	flag.BoolVar(&quiet, "q", false, "Quiet logging. Totally silent")
 	flag.BoolVar(&veryVerbose, "vv", false, "Enable very verbose logging")
@@ -276,6 +282,17 @@ Developer Options:
 	flag.StringVar(&memprofile, "memprofile", "", "write memory profile to `file`")
 	flag.Parse()
 
+	if logEncoding == "json" {
+		log.LogJSON = true
+		data, _ := os.ReadFile(filepath.Join(dir, "config"))
+		if gjson.GetBytes(data, "logconfig.encoding").String() == "json" {
+			c := gjson.GetBytes(data, "logconfig").String()
+			log.Build(c)
+		} else {
+			log.Build("")
+		}
+	}
+
 	var logw io.Writer = os.Stderr
 	if quiet {
 		logw = ioutil.Discard
@@ -292,6 +309,7 @@ Developer Options:
 	} else {
 		log.Level = 1
 	}
+
 	core.DevMode = devMode
 	core.ShowDebugMessages = veryVerbose
 
@@ -409,17 +427,22 @@ Developer Options:
 		saddr = fmt.Sprintf("Port: %d", port)
 	}
 
-	fmt.Fprintf(logw, `
+	if log.LogJSON {
-   _____ _ _     ___ ___
+		log.Printf(`Tile38 %s%s %d bit (%s/%s) %s%s, PID: %d. Visit tile38.com/sponsor to support the project`,
-  |_   _|_| |___|_  | . |  Tile38 %s%s %d bit (%s/%s)
+			core.Version, gitsha, strconv.IntSize, runtime.GOARCH, runtime.GOOS, hostd, saddr, os.Getpid())
-    | | | | | -_|_  | . |  %s%s, PID: %d
+	} else {
-    |_| |_|_|___|___|___|  tile38.com
+		fmt.Fprintf(logw, `
+	_____ _ _     ___ ___
+	|_  _|_| |___|_  | . |	Tile38 %s%s %d bit (%s/%s)
+	 | | | | | -_|_  | . |  %s%s, PID: %d
+	 |_| |_|_|___|___|___|  tile38.com
 	 
 Please consider sponsoring Tile38 development, especially if your company
 benefits from this software. Visit tile38.com/sponsor today to learn more.
 
 `, core.Version, gitsha, strconv.IntSize, runtime.GOARCH, runtime.GOOS, hostd,
-		saddr, os.Getpid())
+			saddr, os.Getpid())
+	}
 
 	if pidferr != nil {
 		log.Warnf("pidfile: %v", pidferr)

go.mod

@@ -31,6 +31,7 @@ require (
 	github.com/tidwall/sjson v1.2.4
 	github.com/xdg/scram v1.0.3
 	github.com/yuin/gopher-lua v0.0.0-20200816102855-ee81675732da
+	go.uber.org/zap v1.13.0
 	golang.org/x/net v0.0.0-20210226172049-e18ecbb05110
 	golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1
 	google.golang.org/api v0.20.0

go.sum

@@ -530,11 +530,15 @@ go.opencensus.io v0.22.2/go.mod h1:yxeiOL68Rb0Xd1ddK5vPZ/oVn4vY4Ynel7k9FzqtOIw=
 go.opencensus.io v0.22.3 h1:8sGtKOrtQqkN1bp2AtX+misvLIlOmsEsNd+9NIcPEm8=
 go.opencensus.io v0.22.3/go.mod h1:yxeiOL68Rb0Xd1ddK5vPZ/oVn4vY4Ynel7k9FzqtOIw=
 go.uber.org/atomic v1.3.2/go.mod h1:gD2HeocX3+yG+ygLZcrzQJaqmWj9AIm7n08wl/qW/PE=
+go.uber.org/atomic v1.5.0 h1:OI5t8sDa1Or+q8AeE+yKeB/SDYioSHAgcVljj9JIETY=
 go.uber.org/atomic v1.5.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ=
 go.uber.org/multierr v1.1.0/go.mod h1:wR5kodmAFQ0UK8QlbwjlSNy0Z68gJhDJUG5sjR94q/0=
+go.uber.org/multierr v1.3.0 h1:sFPn2GLc3poCkfrpIXGhBD2X0CMIo4Q/zSULXrj/+uc=
 go.uber.org/multierr v1.3.0/go.mod h1:VgVr7evmIr6uPjLBxg28wmKNXyqE9akIJ5XnfpiKl+4=
+go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee h1:0mgffUl7nfd+FpvXMVz4IDEaUSmT1ysygQC7qYo7sG4=
 go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee/go.mod h1:vJERXedbb3MVM5f9Ejo0C68/HhF8uaILCdgjnY+goOA=
 go.uber.org/zap v1.10.0/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q=
+go.uber.org/zap v1.13.0 h1:nR6NoDBgAf67s68NhaXbsojM+2gxp3S1hWkHDl27pVU=
 go.uber.org/zap v1.13.0/go.mod h1:zwrFLgMcdUuIBviXEYEH1YKNaOBnKXsx2IPda5bBwHM=
 golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
 golang.org/x/crypto v0.0.0-20181029021203-45a5f77698d3/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=

internal/log/log.go

@@ -1,18 +1,22 @@
 package log
 
 import (
+	"encoding/json"
 	"fmt"
 	"io"
 	"os"
 	"sync"
 	"time"
 
+	"go.uber.org/zap"
 	"golang.org/x/term"
 )
 
 var mu sync.Mutex
 var wr io.Writer
 var tty bool
+var LogJSON = false
+var logger *zap.SugaredLogger
 
 // Level is the log level
 // 0: silent  - do not log
@@ -28,6 +32,54 @@ func SetOutput(w io.Writer) {
 	wr = w
 }
 
+// Build a zap logger from default or custom config
+func Build(c string) error {
+	if c == "" {
+		zcfg := zap.NewProductionConfig()
+
+		// to be able to filter with Tile38 levels
+		zcfg.Level.SetLevel(zap.DebugLevel)
+		// disable caller because caller is always log.go
+		zcfg.DisableCaller = true
+
+		core, err := zcfg.Build()
+		if err != nil {
+			return err
+		}
+		defer core.Sync()
+		logger = core.Sugar()
+	} else {
+		var zcfg zap.Config
+		err := json.Unmarshal([]byte(c), &zcfg)
+		if err != nil {
+			return err
+		}
+
+		// to be able to filter with Tile38 levels
+		zcfg.Level.SetLevel(zap.DebugLevel)
+		// disable caller because caller is always log.go
+		zcfg.DisableCaller = true
+
+		core, err := zcfg.Build()
+		if err != nil {
+			return err
+		}
+		defer core.Sync()
+		logger = core.Sugar()
+	}
+	return nil
+}
+
+// Set a zap logger
+func Set(sl *zap.SugaredLogger) {
+	logger = sl
+}
+
+// Get a zap logger
+func Get() *zap.SugaredLogger {
+	return logger
+}
+
 func init() {
 	SetOutput(os.Stderr)
 }
@@ -71,6 +123,10 @@ var emptyFormat string
 // Infof ...
 func Infof(format string, args ...interface{}) {
 	if Level >= 1 {
+		if LogJSON {
+			logger.Infof(format, args...)
+			return
+		}
 		log(1, "INFO", "\x1b[36m", true, format, args...)
 	}
 }
@@ -78,6 +134,10 @@ func Infof(format string, args ...interface{}) {
 // Info ...
 func Info(args ...interface{}) {
 	if Level >= 1 {
+		if LogJSON {
+			logger.Info(args...)
+			return
+		}
 		log(1, "INFO", "\x1b[36m", false, emptyFormat, args...)
 	}
 }
@@ -85,6 +145,10 @@ func Info(args ...interface{}) {
 // HTTPf ...
 func HTTPf(format string, args ...interface{}) {
 	if Level >= 1 {
+		if LogJSON {
+			logger.Infof(format, args...)
+			return
+		}
 		log(1, "HTTP", "\x1b[1m\x1b[30m", true, format, args...)
 	}
 }
@@ -92,6 +156,10 @@ func HTTPf(format string, args ...interface{}) {
 // HTTP ...
 func HTTP(args ...interface{}) {
 	if Level >= 1 {
+		if LogJSON {
+			logger.Info(args...)
+			return
+		}
 		log(1, "HTTP", "\x1b[1m\x1b[30m", false, emptyFormat, args...)
 	}
 }
@@ -99,6 +167,10 @@ func HTTP(args ...interface{}) {
 // Errorf ...
 func Errorf(format string, args ...interface{}) {
 	if Level >= 1 {
+		if LogJSON {
+			logger.Errorf(format, args...)
+			return
+		}
 		log(1, "ERRO", "\x1b[1m\x1b[31m", true, format, args...)
 	}
 }
@@ -106,6 +178,10 @@ func Errorf(format string, args ...interface{}) {
 // Error ..
 func Error(args ...interface{}) {
 	if Level >= 1 {
+		if LogJSON {
+			logger.Errorf(emptyFormat, args...)
+			return
+		}
 		log(1, "ERRO", "\x1b[1m\x1b[31m", false, emptyFormat, args...)
 	}
 }
@@ -113,6 +189,10 @@ func Error(args ...interface{}) {
 // Warnf ...
 func Warnf(format string, args ...interface{}) {
 	if Level >= 1 {
+		if LogJSON {
+			logger.Warnf(format, args...)
+			return
+		}
 		log(2, "WARN", "\x1b[33m", true, format, args...)
 	}
 }
@@ -120,6 +200,10 @@ func Warnf(format string, args ...interface{}) {
 // Warn ...
 func Warn(args ...interface{}) {
 	if Level >= 1 {
+		if LogJSON {
+			logger.Warnf(emptyFormat, args...)
+			return
+		}
 		log(2, "WARN", "\x1b[33m", false, emptyFormat, args...)
 	}
 }
@@ -127,6 +211,10 @@ func Warn(args ...interface{}) {
 // Debugf ...
 func Debugf(format string, args ...interface{}) {
 	if Level >= 3 {
+		if LogJSON {
+			logger.Debugf(format, args...)
+			return
+		}
 		log(3, "DEBU", "\x1b[35m", true, format, args...)
 	}
 }
@@ -134,6 +222,10 @@ func Debugf(format string, args ...interface{}) {
 // Debug ...
 func Debug(args ...interface{}) {
 	if Level >= 3 {
+		if LogJSON {
+			logger.Debugf(emptyFormat, args...)
+			return
+		}
 		log(3, "DEBU", "\x1b[35m", false, emptyFormat, args...)
 	}
 }
@@ -144,18 +236,29 @@ func Printf(format string, args ...interface{}) {
 }
 
 // Print ...
-func Print(format string, args ...interface{}) {
+func Print(args ...interface{}) {
 	Info(args...)
 }
 
 // Fatalf ...
 func Fatalf(format string, args ...interface{}) {
+	if LogJSON {
+		logger.Fatalf(format, args...)
+		os.Exit(1)
+		return
+	}
+
 	log(1, "FATA", "\x1b[31m", true, format, args...)
 	os.Exit(1)
 }
 
 // Fatal ...
 func Fatal(args ...interface{}) {
+	if LogJSON {
+		logger.Fatalf(emptyFormat, args...)
+		os.Exit(1)
+		return
+	}
 	log(1, "FATA", "\x1b[31m", false, emptyFormat, args...)
 	os.Exit(1)
 }

internal/log/log_test.go

@@ -5,10 +5,15 @@ import (
 	"io/ioutil"
 	"strings"
 	"testing"
+
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+	"go.uber.org/zap/zaptest/observer"
 )
 
 func TestLog(t *testing.T) {
 	f := &bytes.Buffer{}
+	LogJSON = false
 	SetOutput(f)
 	Printf("hello %v", "everyone")
 	if !strings.HasSuffix(f.String(), "hello everyone\n") {
@@ -16,10 +21,200 @@ func TestLog(t *testing.T) {
 	}
 }
 
+func TestLogJSON(t *testing.T) {
+
+	LogJSON = true
+	Build("")
+
+	type tcase struct {
+		level  int
+		format string
+		args   string
+		ops    func(...interface{})
+		fops   func(string, ...interface{})
+		expMsg string
+		expLvl zapcore.Level
+	}
+
+	fn := func(tc tcase) func(*testing.T) {
+		return func(t *testing.T) {
+			observedZapCore, observedLogs := observer.New(zap.DebugLevel)
+			Set(zap.New(observedZapCore).Sugar())
+			Level = tc.level
+
+			if tc.format != "" {
+				tc.fops(tc.format, tc.args)
+			} else {
+				tc.ops(tc.args)
+			}
+
+			if observedLogs.Len() < 1 {
+				t.Fatal("fail")
+			}
+
+			allLogs := observedLogs.All()
+
+			if allLogs[0].Message != tc.expMsg {
+				t.Fatal("fail")
+			}
+
+			if allLogs[0].Level != tc.expLvl {
+				t.Fatal("fail")
+			}
+		}
+	}
+
+	tests := map[string]tcase{
+		"Print": {
+			level: 1,
+			args:  "Print json logger",
+			ops: func(args ...interface{}) {
+				Print(args...)
+			},
+			expMsg: "Print json logger",
+			expLvl: zapcore.InfoLevel,
+		},
+		"Printf": {
+			level:  1,
+			format: "Printf json %v",
+			args:   "logger",
+			fops: func(format string, args ...interface{}) {
+				Printf(format, args...)
+			},
+			expMsg: "Printf json logger",
+			expLvl: zapcore.InfoLevel,
+		},
+		"Info": {
+			level: 1,
+			args:  "Info json logger",
+			ops: func(args ...interface{}) {
+				Info(args...)
+			},
+			expMsg: "Info json logger",
+			expLvl: zapcore.InfoLevel,
+		},
+		"Infof": {
+			level:  1,
+			format: "Infof json %v",
+			args:   "logger",
+			fops: func(format string, args ...interface{}) {
+				Infof(format, args...)
+			},
+			expMsg: "Infof json logger",
+			expLvl: zapcore.InfoLevel,
+		},
+		"Debug": {
+			level: 3,
+			args:  "Debug json logger",
+			ops: func(args ...interface{}) {
+				Debug(args...)
+			},
+			expMsg: "Debug json logger",
+			expLvl: zapcore.DebugLevel,
+		},
+		"Debugf": {
+			level:  3,
+			format: "Debugf json %v",
+			args:   "logger",
+			fops: func(format string, args ...interface{}) {
+				Debugf(format, args...)
+			},
+			expMsg: "Debugf json logger",
+			expLvl: zapcore.DebugLevel,
+		},
+		"Warn": {
+			level: 2,
+			args:  "Warn json logger",
+			ops: func(args ...interface{}) {
+				Warn(args...)
+			},
+			expMsg: "Warn json logger",
+			expLvl: zapcore.WarnLevel,
+		},
+		"Warnf": {
+			level:  2,
+			format: "Warnf json %v",
+			args:   "logger",
+			fops: func(format string, args ...interface{}) {
+				Warnf(format, args...)
+			},
+			expMsg: "Warnf json logger",
+			expLvl: zapcore.WarnLevel,
+		},
+		"Error": {
+			level: 1,
+			args:  "Error json logger",
+			ops: func(args ...interface{}) {
+				Error(args...)
+			},
+			expMsg: "Error json logger",
+			expLvl: zapcore.ErrorLevel,
+		},
+		"Errorf": {
+			level:  1,
+			format: "Errorf json %v",
+			args:   "logger",
+			fops: func(format string, args ...interface{}) {
+				Errorf(format, args...)
+			},
+			expMsg: "Errorf json logger",
+			expLvl: zapcore.ErrorLevel,
+		},
+		"Http": {
+			level: 1,
+			args:  "Http json logger",
+			ops: func(args ...interface{}) {
+				HTTP(args...)
+			},
+			expMsg: "Http json logger",
+			expLvl: zapcore.InfoLevel,
+		},
+		"Httpf": {
+			level:  1,
+			format: "Httpf json %v",
+			args:   "logger",
+			fops: func(format string, args ...interface{}) {
+				HTTPf(format, args...)
+			},
+			expMsg: "Httpf json logger",
+			expLvl: zapcore.InfoLevel,
+		},
+	}
+
+	for name, tc := range tests {
+		t.Run(name, fn(tc))
+	}
+}
+
 func BenchmarkLogPrintf(t *testing.B) {
+	LogJSON = false
+	Level = 1
 	SetOutput(ioutil.Discard)
 	t.ResetTimer()
 	for i := 0; i < t.N; i++ {
 		Printf("X %s", "Y")
 	}
 }
+
+func BenchmarkLogJSONPrintf(t *testing.B) {
+	LogJSON = true
+	Level = 1
+
+	ec := zap.NewProductionEncoderConfig()
+	ec.EncodeDuration = zapcore.NanosDurationEncoder
+	ec.EncodeTime = zapcore.EpochNanosTimeEncoder
+	enc := zapcore.NewJSONEncoder(ec)
+
+	logger := zap.New(
+		zapcore.NewCore(
+			enc,
+			zapcore.AddSync(ioutil.Discard),
+			zap.DebugLevel,
+		)).Sugar()
+
+	Set(logger)
+	t.ResetTimer()
+	for i := 0; i < t.N; i++ {
+		Printf("X %s", "Y")
+	}
+}

internal/server/config.go

@@ -33,9 +33,10 @@ const (
 	MaxMemory     = "maxmemory"
 	AutoGC        = "autogc"
 	KeepAlive     = "keepalive"
+	LogConfig     = "logconfig"
 )
 
-var validProperties = []string{RequirePass, LeaderAuth, ProtectedMode, MaxMemory, AutoGC, KeepAlive}
+var validProperties = []string{RequirePass, LeaderAuth, ProtectedMode, MaxMemory, AutoGC, KeepAlive, LogConfig}
 
 // Config is a tile38 config
 type Config struct {
@@ -62,6 +63,8 @@ type Config struct {
 	_autoGC         uint64
 	_keepAliveP     string
 	_keepAlive      int64
+	_logConfigP     interface{}
+	_logConfig      string
 }
 
 func loadConfig(path string) (*Config, error) {
@@ -90,7 +93,9 @@ func loadConfig(path string) (*Config, error) {
 		_maxMemoryP:     gjson.Get(json, MaxMemory).String(),
 		_autoGCP:        gjson.Get(json, AutoGC).String(),
 		_keepAliveP:     gjson.Get(json, KeepAlive).String(),
+		_logConfig:      gjson.Get(json, LogConfig).String(),
 	}
+
 	// load properties
 	if err := config.setProperty(RequirePass, config._requirePassP, true); err != nil {
 		return nil, err
@@ -110,6 +115,9 @@ func loadConfig(path string) (*Config, error) {
 	if err := config.setProperty(KeepAlive, config._keepAliveP, true); err != nil {
 		return nil, err
 	}
+	if err := config.setProperty(LogConfig, config._logConfig, true); err != nil {
+		return nil, err
+	}
 	config.write(false)
 	return config, nil
 }
@@ -138,6 +146,9 @@ func (config *Config) write(writeProperties bool) {
 		} else {
 			config._keepAliveP = strconv.FormatUint(uint64(config._keepAlive), 10)
 		}
+		if config._logConfig != "" {
+			config._logConfigP = config._logConfig
+		}
 	}
 
 	m := make(map[string]interface{})
@@ -177,6 +188,11 @@ func (config *Config) write(writeProperties bool) {
 	if config._keepAliveP != "" {
 		m[KeepAlive] = config._keepAliveP
 	}
+	if config._logConfigP != "" {
+		var lcfg map[string]interface{}
+		json.Unmarshal([]byte(config._logConfig), &lcfg)
+		m[LogConfig] = lcfg
+	}
 	data, err := json.MarshalIndent(m, "", "\t")
 	if err != nil {
 		panic(err)
@@ -285,6 +301,12 @@ func (config *Config) setProperty(name, value string, fromLoad bool) error {
 				config._keepAlive = int64(keepalive)
 			}
 		}
+	case LogConfig:
+		if value == "" {
+			config._logConfig = ""
+		} else {
+			config._logConfig = value
+		}
 	}
 
 	if invalid {
@@ -322,6 +344,8 @@ func (config *Config) getProperty(name string) string {
 		return formatMemSize(config._maxMemory)
 	case KeepAlive:
 		return strconv.FormatUint(uint64(config._keepAlive), 10)
+	case LogConfig:
+		return config._logConfig
 	}
 }
 
@@ -460,3 +484,9 @@ func (config *Config) setReadOnly(v bool) {
 	config._readOnly = v
 	config.mu.Unlock()
 }
+func (config *Config) logConfig() string {
+	config.mu.RLock()
+	v := config._logConfig
+	config.mu.RUnlock()
+	return v
+}

internal/server/server.go

@@ -153,6 +153,7 @@ func Serve(opts Options) error {
 	if core.QueueFileName == "" {
 		core.QueueFileName = path.Join(opts.Dir, "queue.db")
 	}
+
 	log.Infof("Server started, Tile38 version %s, git %s", core.Version, core.GitSHA)
 
 	// Initialize the s