diff --git a/cmd/tile38-server/main.go b/cmd/tile38-server/main.go index f7bc9503..fe16aa68 100644 --- a/cmd/tile38-server/main.go +++ b/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, ` - _____ _ _ ___ ___ - |_ _|_| |___|_ | . | Tile38 %s%s %d bit (%s/%s) - | | | | | -_|_ | . | %s%s, PID: %d - |_| |_|_|___|___|___| tile38.com - + if log.LogJSON { + log.Printf(`Tile38 %s%s %d bit (%s/%s) %s%s, PID: %d. Visit tile38.com/sponsor to support the project`, + core.Version, gitsha, strconv.IntSize, runtime.GOARCH, runtime.GOOS, hostd, saddr, os.Getpid()) + } else { + 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) diff --git a/go.mod b/go.mod index a2d59d94..67f1c68b 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index cfa4887e..97b9c7f3 100644 --- a/go.sum +++ b/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= diff --git a/internal/log/log.go b/internal/log/log.go index b94c9b41..bdcfe3bc 100644 --- a/internal/log/log.go +++ b/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) } diff --git a/internal/log/log_test.go b/internal/log/log_test.go index 1f2c5b0c..f1169615 100644 --- a/internal/log/log_test.go +++ b/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") + } +} diff --git a/internal/server/config.go b/internal/server/config.go index 7b55fc6d..d5d9030b 100644 --- a/internal/server/config.go +++ b/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 +} diff --git a/internal/server/server.go b/internal/server/server.go index 2bbaaa81..74a0a607 100644 --- a/internal/server/server.go +++ b/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