From 4765cdbd9348ab811f30ed9801bf775c69da6262 Mon Sep 17 00:00:00 2001 From: "x.zhou" Date: Mon, 25 Dec 2023 11:04:23 +0800 Subject: [PATCH] feat: add logging package --- .gitignore | 3 +- cmd/app.go | 27 +- cmd/list.go | 11 +- cmd/mkdir.go | 9 +- cmd/pull.go | 3 +- cmd/push.go | 3 +- cmd/rm.go | 3 +- cmd/rmdir.go | 6 +- cmd/stat.go | 7 +- go.mod | 10 +- go.sum | 14 +- pkg/logging/broadcast.go | 29 +++ pkg/logging/ctx.go | 54 ++++ pkg/logging/logfile.go | 493 ++++++++++++++++++++++++++++++++++++ pkg/logging/logging.go | 33 +++ pkg/logging/logging_test.go | 154 +++++++++++ pkg/logging/null_logger.go | 12 + pkg/logging/zaplogutil.go | 139 ++++++++++ 18 files changed, 978 insertions(+), 32 deletions(-) create mode 100644 pkg/logging/broadcast.go create mode 100644 pkg/logging/ctx.go create mode 100644 pkg/logging/logfile.go create mode 100644 pkg/logging/logging.go create mode 100644 pkg/logging/logging_test.go create mode 100644 pkg/logging/null_logger.go create mode 100644 pkg/logging/zaplogutil.go diff --git a/.gitignore b/.gitignore index f3d6549..fb60f34 100644 --- a/.gitignore +++ b/.gitignore @@ -1 +1,2 @@ -/build/ \ No newline at end of file +/build/ +/logs/ \ No newline at end of file diff --git a/cmd/app.go b/cmd/app.go index 0e9b465..44ed24e 100644 --- a/cmd/app.go +++ b/cmd/app.go @@ -1,6 +1,7 @@ package cmd import ( + "context" "fmt" "os" "path/filepath" @@ -9,6 +10,7 @@ import ( "github.com/spf13/cobra" "github.com/apecloud/datasafed/pkg/config" + "github.com/apecloud/datasafed/pkg/logging" "github.com/apecloud/datasafed/pkg/storage" "github.com/apecloud/datasafed/pkg/storage/rclone" ) @@ -20,24 +22,39 @@ const ( var ( rootCmd = &cobra.Command{ - Use: "datasafed", - Short: "`datasafed` is a command line tool for managing remote storages.", + Use: "datasafed", + Short: "`datasafed` is a command line tool for managing remote storages.", + SilenceErrors: true, + SilenceUsage: true, } configFile string doNotInitStorage bool globalStorage storage.Storage + appCtx context.Context = context.Background() + onFinishFuncs []func() ) func init() { rootCmd.PersistentPreRunE = func(cmd *cobra.Command, args []string) error { - if doNotInitStorage { - return nil + appCtx = logging.WithLogger(appCtx, logging.DefaultLoggerFactory) + if !doNotInitStorage { + if err := initStorage(); err != nil { + return err + } } - return initStorage() + return nil + } + rootCmd.PersistentPostRunE = func(cmd *cobra.Command, args []string) error { + for _, fn := range onFinishFuncs { + fn() + } + return nil } rootCmd.PersistentFlags().StringVarP(&configFile, "conf", "c", "/etc/datasafed/datasafed.conf", "config file") + + logging.Attach(rootCmd) } // RootCommand returns the root command. diff --git a/cmd/list.go b/cmd/list.go index 9425b45..61c37d6 100644 --- a/cmd/list.go +++ b/cmd/list.go @@ -2,7 +2,6 @@ package cmd import ( "cmp" - "context" "encoding/json" "fmt" "os" @@ -46,14 +45,14 @@ datasafed list / # List one file and extract its size datasafed list somefile.txt -o long | awk '{print $2}' -# List all files under the directory -datasafed list -r -f /some/dir +# List all files under the directory (ends with '/') +datasafed list -r -f /some/dir/ # List files modified within 1 hour and sort the result by size -datasafed list -r -f -s size --newer-than $(( $(date +%s) - 3600 )) /some/dir +datasafed list -r -f -s size --newer-than $(( $(date +%s) - 3600 )) /some/dir/ # List files with the name pattern -datasafed list --name "*.txt" /some/dir +datasafed list --name "*.txt" /some/dir/ `), Args: cobra.ExactArgs(1), Run: func(cmd *cobra.Command, args []string) { @@ -96,7 +95,7 @@ func doList(opts *listOptions, cmd *cobra.Command, args []string) { Recursive: opts.recursive, MaxDepth: opts.maxDepth, } - entries, err := globalStorage.List(context.Background(), rpath, lopts) + entries, err := globalStorage.List(appCtx, rpath, lopts) exitIfError(err) entries = filterEntries(entries, opts) diff --git a/cmd/mkdir.go b/cmd/mkdir.go index 9ccb7c9..58847ee 100644 --- a/cmd/mkdir.go +++ b/cmd/mkdir.go @@ -1,7 +1,6 @@ package cmd import ( - "context" "strings" "github.com/spf13/cobra" @@ -9,8 +8,10 @@ import ( func init() { cmd := &cobra.Command{ - Use: "mkdir rpath", - Short: "Create an empty remote directory.", + Use: "mkdir rpath", + Short: "Create an empty remote directory." + + "Some storage backends, such as S3, do not have the concept of a directory, " + + "in which case the command will directly return success with no effect.", Example: strings.TrimSpace(` # Create an empty directory datasafed mkdir some/dir @@ -22,6 +23,6 @@ datasafed mkdir some/dir } func doMkdir(cmd *cobra.Command, args []string) { - err := globalStorage.Mkdir(context.Background(), args[0]) + err := globalStorage.Mkdir(appCtx, args[0]) exitIfError(err) } diff --git a/cmd/pull.go b/cmd/pull.go index 5b7a38e..4c1e9e3 100644 --- a/cmd/pull.go +++ b/cmd/pull.go @@ -1,7 +1,6 @@ package cmd import ( - "context" "fmt" "io" "os" @@ -51,7 +50,7 @@ func doPull(cmd *cobra.Command, args []string) { defer f.Close() out = f } - err := globalStorage.Pull(context.Background(), rpath, out) + err := globalStorage.Pull(appCtx, rpath, out) if err != nil { err = fmt.Errorf("pull %q: %w", rpath, err) } diff --git a/cmd/push.go b/cmd/push.go index 2c4eaf7..0c7c540 100644 --- a/cmd/push.go +++ b/cmd/push.go @@ -1,7 +1,6 @@ package cmd import ( - "context" "fmt" "io" "os" @@ -40,7 +39,7 @@ func doPush(cmd *cobra.Command, args []string) { defer f.Close() in = f } - err := globalStorage.Push(context.Background(), in, rpath) + err := globalStorage.Push(appCtx, in, rpath) if err != nil { err = fmt.Errorf("push to %q: %w", rpath, err) } diff --git a/cmd/rm.go b/cmd/rm.go index e40b0c2..3e3d124 100644 --- a/cmd/rm.go +++ b/cmd/rm.go @@ -1,7 +1,6 @@ package cmd import ( - "context" "strings" "github.com/spf13/cobra" @@ -33,6 +32,6 @@ datasafed rm -r some/path/to/dir } func doRm(opts *rmOptions, cmd *cobra.Command, args []string) { - err := globalStorage.Remove(context.Background(), args[0], opts.recursive) + err := globalStorage.Remove(appCtx, args[0], opts.recursive) exitIfError(err) } diff --git a/cmd/rmdir.go b/cmd/rmdir.go index c850023..e0cefcf 100644 --- a/cmd/rmdir.go +++ b/cmd/rmdir.go @@ -1,7 +1,6 @@ package cmd import ( - "context" "strings" "github.com/spf13/cobra" @@ -11,6 +10,9 @@ func init() { cmd := &cobra.Command{ Use: "rmdir rpath", Short: "Remove an empty remote directory.", + Long: "Remove an empty remote directory.\n" + + "Some storage backends, such as S3, do not have the concept of a directory, " + + "in which case the command will directly return success with no effect.", Example: strings.TrimSpace(` # Remove an empty directory datasafed rmdir some/dir @@ -22,6 +24,6 @@ datasafed rmdir some/dir } func doRmdir(cmd *cobra.Command, args []string) { - err := globalStorage.Rmdir(context.Background(), args[0]) + err := globalStorage.Rmdir(appCtx, args[0]) exitIfError(err) } diff --git a/cmd/stat.go b/cmd/stat.go index ecaafc5..59a139c 100644 --- a/cmd/stat.go +++ b/cmd/stat.go @@ -1,7 +1,6 @@ package cmd import ( - "context" "encoding/json" "fmt" "strings" @@ -23,8 +22,8 @@ func init() { # Stat a file datasafed stat path/to/file.txt -# Stat a directory with json output -datasafed stat -json path/to/dir +# Stat a directory (ends with '/') with json output +datasafed stat -json path/to/dir/ `), Args: cobra.ExactArgs(1), Run: func(cmd *cobra.Command, args []string) { @@ -37,7 +36,7 @@ datasafed stat -json path/to/dir func doStat(opts *statOptions, cmd *cobra.Command, args []string) { rpath := args[0] - result, err := globalStorage.Stat(context.Background(), rpath) + result, err := globalStorage.Stat(appCtx, rpath) exitIfError(err) if !opts.json { fmt.Printf("TotalSize: %d\n", result.TotalSize) diff --git a/go.mod b/go.mod index 9fc195e..97a07ba 100644 --- a/go.mod +++ b/go.mod @@ -3,8 +3,11 @@ module github.com/apecloud/datasafed go 1.21 require ( + github.com/fatih/color v1.16.0 github.com/rclone/rclone v1.63.1 github.com/spf13/cobra v1.7.0 + github.com/stretchr/testify v1.8.3 + go.uber.org/zap v1.26.0 gopkg.in/ini.v1 v1.67.0 ) @@ -28,6 +31,7 @@ require ( github.com/colinmarc/hdfs/v2 v2.3.0 // indirect github.com/coreos/go-semver v0.3.1 // indirect github.com/cpuguy83/go-md2man/v2 v2.0.2 // indirect + github.com/davecgh/go-spew v1.1.1 // indirect github.com/dropbox/dropbox-sdk-go-unofficial/v6 v6.0.5 // indirect github.com/gabriel-vasile/mimetype v1.4.2 // indirect github.com/geoffgarside/ber v1.1.0 // indirect @@ -66,7 +70,7 @@ require ( github.com/kylelemons/godebug v1.1.0 // indirect github.com/lufia/plan9stats v0.0.0-20211012122336-39d0f177ccd0 // indirect github.com/mattn/go-colorable v0.1.13 // indirect - github.com/mattn/go-isatty v0.0.16 // indirect + github.com/mattn/go-isatty v0.0.20 // indirect github.com/matttproud/golang_protobuf_extensions v1.0.1 // indirect github.com/mitchellh/go-homedir v1.1.0 // indirect github.com/ncw/go-acd v0.0.0-20201019170801-fe55f33415b1 // indirect @@ -77,6 +81,7 @@ require ( github.com/pkg/browser v0.0.0-20210911075715-681adbf594b8 // indirect github.com/pkg/sftp v1.13.6-0.20230213180117-971c283182b6 // indirect github.com/pkg/xattr v0.4.9 // indirect + github.com/pmezard/go-difflib v1.0.0 // indirect github.com/power-devops/perfstat v0.0.0-20210106213030-5aafc221ea8c // indirect github.com/prometheus/client_golang v1.14.0 // indirect github.com/prometheus/client_model v0.3.0 // indirect @@ -106,11 +111,12 @@ require ( github.com/zeebo/errs v1.3.0 // indirect go.etcd.io/bbolt v1.3.7 // indirect go.opencensus.io v0.24.0 // indirect + go.uber.org/multierr v1.10.0 // indirect golang.org/x/crypto v0.7.0 // indirect golang.org/x/net v0.8.0 // indirect golang.org/x/oauth2 v0.6.0 // indirect golang.org/x/sync v0.1.0 // indirect - golang.org/x/sys v0.8.0 // indirect + golang.org/x/sys v0.14.0 // indirect golang.org/x/term v0.7.0 // indirect golang.org/x/text v0.8.0 // indirect golang.org/x/time v0.3.0 // indirect diff --git a/go.sum b/go.sum index 6673ef9..1384ceb 100644 --- a/go.sum +++ b/go.sum @@ -105,6 +105,8 @@ github.com/envoyproxy/go-control-plane v0.9.0/go.mod h1:YTl/9mNaCwkRvm6d1a2C3ymF github.com/envoyproxy/go-control-plane v0.9.1-0.20191026205805-5f8ba28d4473/go.mod h1:YTl/9mNaCwkRvm6d1a2C3ymFceY/DCBVvsKhRF0iEA4= github.com/envoyproxy/go-control-plane v0.9.4/go.mod h1:6rpuAdCZL397s3pYoYcLgu1mIlRU8Am5FuJP05cCM98= github.com/envoyproxy/protoc-gen-validate v0.1.0/go.mod h1:iSmxcyjqTsJpI2R4NaDN7+kN2VEUnK/pcBlmesArF7c= +github.com/fatih/color v1.16.0 h1:zmkK9Ngbjj+K0yRhTVONQh1p/HknKYSlNT+vZCzyokM= +github.com/fatih/color v1.16.0/go.mod h1:fL2Sau1YI5c0pdGEVCbKQbLXB6edEj1ZgiY4NijnWvE= github.com/fsnotify/fsnotify v1.6.0 h1:n+5WquG0fcWoWp6xPWfHdbskMCQaFnG6PfBrh1Ky4HY= github.com/fsnotify/fsnotify v1.6.0/go.mod h1:sl3t1tCWJFWoRz9R8WJCbQihKKwmorjAbSClcnxKAGw= github.com/gabriel-vasile/mimetype v1.4.2 h1:w5qFW6JKBz9Y393Y4q372O9A7cUSequkh1Q7OhCmWKU= @@ -283,8 +285,9 @@ github.com/lufia/plan9stats v0.0.0-20211012122336-39d0f177ccd0 h1:6E+4a0GO5zZEnZ github.com/lufia/plan9stats v0.0.0-20211012122336-39d0f177ccd0/go.mod h1:zJYVVT2jmtg6P3p1VtQj7WsuWi/y4VnjVBn7F8KPB3I= github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA= github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg= -github.com/mattn/go-isatty v0.0.16 h1:bq3VjFmv/sOjHtdEhmkEV4x1AJtvUvOJ2PFAZ5+peKQ= github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= +github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY= +github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= github.com/matttproud/golang_protobuf_extensions v1.0.1 h1:4hp9jkHxhMHkqkrB3Ix0jegS5sx/RkqARlsWZ6pIwiU= github.com/matttproud/golang_protobuf_extensions v1.0.1/go.mod h1:D8He9yQNgCq6Z5Ld7szi9bcBfOoFv/3dc6xSMkL2PC0= github.com/miekg/dns v1.1.42/go.mod h1:+evo5L0630/F6ca/Z9+GAqzhjGyn8/c+TBaOyfEl0V4= @@ -444,6 +447,12 @@ go.opencensus.io v0.22.3/go.mod h1:yxeiOL68Rb0Xd1ddK5vPZ/oVn4vY4Ynel7k9FzqtOIw= go.opencensus.io v0.22.4/go.mod h1:yxeiOL68Rb0Xd1ddK5vPZ/oVn4vY4Ynel7k9FzqtOIw= go.opencensus.io v0.24.0 h1:y73uSU6J157QMP2kn2r30vwW1A2W2WFwSCGnAVxeaD0= go.opencensus.io v0.24.0/go.mod h1:vNK8G9p7aAivkbmorf4v+7Hgx+Zs0yY+0fOtgBfjQKo= +go.uber.org/goleak v1.2.0 h1:xqgm/S+aQvhWFTtR0XK3Jvg7z8kGV8P4X14IzwN3Eqk= +go.uber.org/goleak v1.2.0/go.mod h1:XJYK+MuIchqpmGmUSAzotztawfKvYLUIgg7guXrwVUo= +go.uber.org/multierr v1.10.0 h1:S0h4aNzvfcFsC3dRF1jLoaov7oRaKqRGC/pUEJ2yvPQ= +go.uber.org/multierr v1.10.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y= +go.uber.org/zap v1.26.0 h1:sI7k6L95XOKS281NhVKOFCUNIvv9e0w4BF8N3u+tCRo= +go.uber.org/zap v1.26.0/go.mod h1:dtElttAiwGvoJ/vj4IwHBS/gXsEu/pZ50mUIRWuG0so= golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/crypto v0.0.0-20190510104115-cbcb75029529/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI= @@ -610,8 +619,9 @@ golang.org/x/sys v0.1.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.2.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.5.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.8.0 h1:EBmGv8NaZBZTWvrbjNoL6HVt+IVy3QDQpJs7VRIw3tU= golang.org/x/sys v0.8.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.14.0 h1:Vz7Qs629MkJkGyHxUlRHizWJRG2j8fbQKjELVSNhy7Q= +golang.org/x/sys v0.14.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= golang.org/x/term v0.0.0-20210927222741-03fcf44c2211/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8= golang.org/x/term v0.1.0/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8= diff --git a/pkg/logging/broadcast.go b/pkg/logging/broadcast.go new file mode 100644 index 0000000..af2504d --- /dev/null +++ b/pkg/logging/broadcast.go @@ -0,0 +1,29 @@ +package logging + +import ( + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// Broadcast is a logger that broadcasts each log message to multiple loggers. +func Broadcast(logger ...Logger) Logger { + var cores []zapcore.Core + + var singleName string + + for _, l := range logger { + dl := l.Desugar() + + if singleName == "" { + singleName = dl.Name() + } + + if dl.Name() != singleName { + singleName = "-" + } + + cores = append(cores, dl.Core()) + } + + return zap.New(zapcore.NewTee(cores...)).Sugar().Named(singleName) +} diff --git a/pkg/logging/ctx.go b/pkg/logging/ctx.go new file mode 100644 index 0000000..2c21b67 --- /dev/null +++ b/pkg/logging/ctx.go @@ -0,0 +1,54 @@ +package logging + +import ( + "context" + "sync" +) + +type contextKey string + +const loggerCacheKey contextKey = "logger" + +type loggerCache struct { + createLoggerForModule LoggerFactory + loggers sync.Map +} + +func (s *loggerCache) getLogger(module string) Logger { + v, ok := s.loggers.Load(module) + if !ok { + v, _ = s.loggers.LoadOrStore(module, s.createLoggerForModule(module)) + } + + return v.(Logger) //nolint:forcetypeassert +} + +// WithLogger returns a derived context with associated logger. +func WithLogger(ctx context.Context, l LoggerFactory) context.Context { + if l == nil { + l = getNullLogger + } + + return context.WithValue(ctx, loggerCacheKey, &loggerCache{ + createLoggerForModule: l, + }) +} + +// WithAdditionalLogger returns a context where all logging is emitted the original output plus the provided logger factory. +func WithAdditionalLogger(ctx context.Context, fact LoggerFactory) context.Context { + originalLogFactory := loggerFactoryFromContext(ctx) + + return WithLogger(ctx, func(module string) Logger { + return Broadcast(originalLogFactory(module), fact(module)) + }) +} + +// loggerFactoryFromContext returns a LoggerFactory associated with current context. +func loggerFactoryFromContext(ctx context.Context) LoggerFactory { + v := ctx.Value(loggerCacheKey) + if v == nil { + return getNullLogger + } + + return v.(*loggerCache).getLogger //nolint:forcetypeassert +} diff --git a/pkg/logging/logfile.go b/pkg/logging/logfile.go new file mode 100644 index 0000000..20fbe9d --- /dev/null +++ b/pkg/logging/logfile.go @@ -0,0 +1,493 @@ +package logging + +import ( + "context" + "fmt" + "io" + "math" + "os" + "path/filepath" + "sort" + "strings" + "sync" + "time" + + "github.com/fatih/color" + "github.com/spf13/cobra" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +const logsDirMode = 0o700 + +var logLevels = []string{"debug", "info", "warning", "error"} + +type loggingFlags struct { + logFile string + logDir string + logDirMaxFiles int + logDirMaxAge time.Duration + logDirMaxTotalSizeMB float64 + logFileMaxSegmentSize int + logLevel string + fileLogLevel string + fileLogLocalTimezone bool + jsonLogFile bool + jsonLogConsole bool + forceColor bool + disableColor bool + consoleLog bool + consoleLogTimestamps bool +} + +func (c *loggingFlags) setup(cmd *cobra.Command) { + f := cmd.PersistentFlags() + f.StringVar(&c.logFile, "log-file", "", "Override log file.") + f.StringVar(&c.logDir, "log-dir", "", "Directory where log files should be written.") + f.IntVar(&c.logDirMaxFiles, "log-dir-max-files", 100, "Maximum number of log files to retain") + f.DurationVar(&c.logDirMaxAge, "log-dir-max-age", 720*time.Hour, "Maximum age of log files to retain") + f.Float64Var(&c.logDirMaxTotalSizeMB, "log-dir-max-total-size-mb", 1000, "Maximum total size of log files to retain") + f.IntVar(&c.logFileMaxSegmentSize, "max-log-file-segment-size", 50000000, "Maximum size of a single log file segment") + f.Var(newEnum(logLevels, &c.logLevel).Default("info"), "log-level", "Console log level") + f.BoolVar(&c.jsonLogConsole, "json-log-console", false, "JSON log file") + f.BoolVar(&c.jsonLogFile, "json-log-file", false, "JSON log file") + f.Var(newEnum(logLevels, &c.fileLogLevel).Default("debug"), "file-log-level", "File log level") + f.BoolVar(&c.fileLogLocalTimezone, "file-log-local-tz", false, "When logging to a file, use local timezone") + f.BoolVar(&c.forceColor, "force-color", false, "Force color output") + f.BoolVar(&c.disableColor, "disable-color", false, "Disable color output") + f.BoolVar(&c.consoleLog, "console-log", false, "Enable console log") + f.BoolVar(&c.consoleLogTimestamps, "console-timestamps", true, "Log timestamps to stderr.") + + old := cmd.PersistentPreRunE + cmd.PersistentPreRunE = func(cmd *cobra.Command, args []string) error { + if err := c.initialize(cmd); err != nil { + return err + } + if old != nil { + return old(cmd, args) + } + return nil + } +} + +// Attach attaches logging flags to the provided application. +func Attach(rootCmd *cobra.Command) { + lf := &loggingFlags{} + lf.setup(rootCmd) +} + +var ( + log = Module("datasafed") + + DefaultLoggerFactory LoggerFactory +) + +const ( + logFileNamePrefix = "datasafed-" + logFileNameSuffix = ".log" +) + +// initialize is invoked as part of command execution to create log file just before it's needed. +func (c *loggingFlags) initialize(cmd *cobra.Command) error { + now := time.Now() + if c.fileLogLocalTimezone { + now = now.Local() + } else { + now = now.UTC() + } + + var cores []zapcore.Core + if c.consoleLog { + cores = append(cores, c.setupConsoleCore(cmd.ErrOrStderr())) + } + if c.logDir != "" { + suffix := strings.ReplaceAll(cmd.Name(), " ", "-") + cores = append(cores, c.setupLogFileCore(now, suffix)) + } + if len(cores) == 0 { + return nil + } + + rootLogger := zap.New(zapcore.NewTee(cores...), zap.WithClock(Clock())) + + DefaultLoggerFactory = func(module string) Logger { + return rootLogger.Named(module).Sugar() + } + + if c.forceColor { + color.NoColor = false + } + + if c.disableColor { + color.NoColor = true + } + + return nil +} + +func (c *loggingFlags) setupConsoleCore(output io.Writer) zapcore.Core { + ec := zapcore.EncoderConfig{ + LevelKey: "l", + MessageKey: "m", + LineEnding: zapcore.DefaultLineEnding, + EncodeTime: zapcore.RFC3339NanoTimeEncoder, + EncodeDuration: zapcore.StringDurationEncoder, + EncodeCaller: zapcore.ShortCallerEncoder, + ConsoleSeparator: " ", + } + + timeFormat := PreciseLayout + + if c.consoleLogTimestamps { + ec.TimeKey = "t" + + if c.jsonLogConsole { + ec.EncodeTime = zapcore.RFC3339NanoTimeEncoder + } else { + // always log local timestamps to the console, not UTC + timeFormat = "15:04:05.000" + ec.EncodeTime = TimezoneAdjust(zapcore.TimeEncoderOfLayout(timeFormat), true) + } + } else { + timeFormat = "" + } + + stec := StdConsoleEncoderConfig{ + TimeLayout: timeFormat, + LocalTime: true, + } + + if c.jsonLogConsole { + ec.EncodeLevel = zapcore.CapitalLevelEncoder + + ec.NameKey = "n" + ec.EncodeName = zapcore.FullNameEncoder + } else { + stec.EmitLogLevel = true + stec.DoNotEmitInfoLevel = true + stec.ColoredLogLevel = !c.disableColor + } + + return zapcore.NewCore( + c.jsonOrConsoleEncoder(stec, ec, c.jsonLogConsole), + zapcore.AddSync(output), + logLevelFromFlag(c.logLevel), + ) +} + +func (c *loggingFlags) setupLogFileBasedLogger(now time.Time, subdir, suffix, logFileOverride string, maxFiles int, maxSizeMB float64, maxAge time.Duration) zapcore.WriteSyncer { + var logFileName, symlinkName string + + if logFileOverride != "" { + var err error + + logFileName, err = filepath.Abs(logFileOverride) + if err != nil { + fmt.Fprintln(os.Stderr, "Unable to resolve logs path", err) + } + } + + if logFileName == "" { + logBaseName := fmt.Sprintf("%v%v-%v-%v%v", logFileNamePrefix, now.Format("20060102-150405"), os.Getpid(), suffix, logFileNameSuffix) + logFileName = filepath.Join(c.logDir, subdir, logBaseName) + symlinkName = "latest.log" + } + + logDir := filepath.Dir(logFileName) + logFileBaseName := filepath.Base(logFileName) + + if err := os.MkdirAll(logDir, logsDirMode); err != nil { + fmt.Fprintln(os.Stderr, "Unable to create logs directory:", err) + } + + sweepLogWG := &sync.WaitGroup{} + doSweep := func() {} + + // do not scrub directory if custom log file has been provided. + if logFileOverride == "" && shouldSweepLog(maxFiles, maxAge) { + doSweep = func() { + sweepLogDir(context.TODO(), logDir, maxFiles, maxSizeMB, maxAge) + } + } + + odf := &onDemandFile{ + logDir: logDir, + logFileBaseName: logFileBaseName, + symlinkName: symlinkName, + maxSegmentSize: c.logFileMaxSegmentSize, + startSweep: func() { + sweepLogWG.Add(1) + + go func() { + defer sweepLogWG.Done() + + doSweep() + }() + }, + } + + // old behavior: start log sweep in parallel to program but don't wait at the end. + odf.startSweep() + + return odf +} + +func (c *loggingFlags) setupLogFileCore(now time.Time, suffix string) zapcore.Core { + return zapcore.NewCore( + c.jsonOrConsoleEncoder( + StdConsoleEncoderConfig{ + TimeLayout: PreciseLayout, + LocalTime: c.fileLogLocalTimezone, + EmitLogLevel: true, + EmitLoggerName: true, + }, + zapcore.EncoderConfig{ + TimeKey: "t", + MessageKey: "m", + NameKey: "n", + LevelKey: "l", + EncodeName: zapcore.FullNameEncoder, + EncodeLevel: zapcore.CapitalLevelEncoder, + EncodeTime: TimezoneAdjust(PreciseTimeEncoder(), c.fileLogLocalTimezone), + EncodeDuration: zapcore.StringDurationEncoder, + ConsoleSeparator: " ", + }, + c.jsonLogFile), + c.setupLogFileBasedLogger(now, "cli-logs", suffix, c.logFile, c.logDirMaxFiles, c.logDirMaxTotalSizeMB, c.logDirMaxAge), + logLevelFromFlag(c.fileLogLevel), + ) +} + +//nolint:gocritic +func (c *loggingFlags) jsonOrConsoleEncoder(ec StdConsoleEncoderConfig, jc zapcore.EncoderConfig, isJSON bool) zapcore.Encoder { + if isJSON { + return zapcore.NewJSONEncoder(jc) + } + + return NewStdConsoleEncoder(ec) +} + +func shouldSweepLog(maxFiles int, maxAge time.Duration) bool { + return maxFiles > 0 || maxAge > 0 +} + +func sweepLogDir(ctx context.Context, dirname string, maxCount int, maxSizeMB float64, maxAge time.Duration) { + var timeCutoff time.Time + if maxAge > 0 { + timeCutoff = time.Now().Add(-maxAge) + } + + if maxCount == 0 { + maxCount = math.MaxInt32 + } + + maxTotalSizeBytes := int64(maxSizeMB * 1e6) + + entries, err := os.ReadDir(dirname) + if err != nil { + log(ctx).Errorf("unable to read log directory: %v", err) + return + } + + fileInfos := make([]os.FileInfo, 0, len(entries)) + + for _, e := range entries { + info, err2 := e.Info() + if os.IsNotExist(err2) { + // we lost the race, the file was deleted since it was listed. + continue + } + + if err2 != nil { + log(ctx).Errorf("unable to read file info: %v", err2) + return + } + + fileInfos = append(fileInfos, info) + } + + sort.Slice(fileInfos, func(i, j int) bool { + return fileInfos[i].ModTime().After(fileInfos[j].ModTime()) + }) + + cnt := 0 + totalSize := int64(0) + + for _, fi := range fileInfos { + if !strings.HasPrefix(fi.Name(), logFileNamePrefix) { + continue + } + + if !strings.HasSuffix(fi.Name(), logFileNameSuffix) { + continue + } + + cnt++ + + totalSize += fi.Size() + + if cnt > maxCount || totalSize > maxTotalSizeBytes || fi.ModTime().Before(timeCutoff) { + if err = os.Remove(filepath.Join(dirname, fi.Name())); err != nil && !os.IsNotExist(err) { + log(ctx).Errorf("unable to remove log file: %v", err) + } + } + } +} + +func logLevelFromFlag(levelString string) zapcore.LevelEnabler { + switch levelString { + case "debug": + return zap.DebugLevel + case "info": + return zap.InfoLevel + case "warning": + return zap.WarnLevel + case "error": + return zap.ErrorLevel + default: + return zap.FatalLevel + } +} + +type onDemandFile struct { + // +checklocks:mu + segmentCounter int // number of segments written + + // +checklocks:mu + currentSegmentSize int // number of bytes written to current segment + + // +checklocks:mu + maxSegmentSize int + + // +checklocks:mu + currentSegmentFilename string + + // +checklocks:mu + logDir string + + // +checklocks:mu + logFileBaseName string + + // +checklocks:mu + symlinkName string + + startSweep func() + + mu sync.Mutex + f *os.File +} + +func (w *onDemandFile) Sync() error { + if w.f == nil { + return nil + } + + //nolint:wrapcheck + return w.f.Sync() +} + +func (w *onDemandFile) closeSegmentAndSweepLocked() { + if w.f != nil { + if err := w.f.Close(); err != nil { + fmt.Fprintf(os.Stderr, "warning: unable to close log segment: %v", err) + } + + w.f = nil + } + + w.startSweep() +} + +func (w *onDemandFile) Write(b []byte) (int, error) { + w.mu.Lock() + defer w.mu.Unlock() + + // close current file if we'd overflow on next write. + if w.f != nil && w.currentSegmentSize+len(b) > w.maxSegmentSize { + w.closeSegmentAndSweepLocked() + } + + // open file if we don't have it yet + if w.f == nil { + var baseName, ext string + + p := strings.LastIndex(w.logFileBaseName, ".") + if p < 0 { + ext = "" + baseName = w.logFileBaseName + } else { + ext = w.logFileBaseName[p:] + baseName = w.logFileBaseName[0:p] + } + + w.currentSegmentFilename = fmt.Sprintf("%s.%d%s", baseName, w.segmentCounter, ext) + w.segmentCounter++ + w.currentSegmentSize = 0 + + lf := filepath.Join(w.logDir, w.currentSegmentFilename) + + f, err := os.Create(lf) //nolint:gosec + if err != nil { + return 0, fmt.Errorf("unable to open log file, %w", err) + } + + w.f = f + + if w.symlinkName != "" { + symlink := filepath.Join(w.logDir, w.symlinkName) + _ = os.Remove(symlink) // best-effort remove + _ = os.Symlink(w.currentSegmentFilename, symlink) // best-effort symlink + } + } + + n, err := w.f.Write(b) + w.currentSegmentSize += n + + //nolint:wrapcheck + return n, err +} + +type enum struct { + Allowed []string + variable *string +} + +// newEnum give a list of allowed flag parameters +func newEnum(allowed []string, variable *string) *enum { + if variable == nil { + panic("variable should not be nil") + } + return &enum{ + Allowed: allowed, + variable: variable, + } +} + +func (a *enum) Default(d string) *enum { + *a.variable = d + return a +} + +func (a enum) String() string { + return *a.variable +} + +func (a *enum) Set(p string) error { + isIncluded := func(opts []string, val string) bool { + for _, opt := range opts { + if val == opt { + return true + } + } + return false + } + if !isIncluded(a.Allowed, p) { + return fmt.Errorf("%s is not included in %s", p, strings.Join(a.Allowed, ",")) + } + *a.variable = p + return nil +} + +func (a *enum) Type() string { + return "string" +} diff --git a/pkg/logging/logging.go b/pkg/logging/logging.go new file mode 100644 index 0000000..7169210 --- /dev/null +++ b/pkg/logging/logging.go @@ -0,0 +1,33 @@ +package logging + +import ( + "context" + "io" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// Logger emits various logs. +type Logger = *zap.SugaredLogger + +// LoggerFactory retrieves a named logger for a given module. +type LoggerFactory func(module string) Logger + +// Module returns an function that returns a logger for a given module when provided with a context. +func Module(module string) func(ctx context.Context) Logger { + return func(ctx context.Context) Logger { + if l := ctx.Value(loggerCacheKey); l != nil { + return l.(*loggerCache).getLogger(module) //nolint:forcetypeassert + } + + return NullLogger + } +} + +// ToWriter returns LoggerFactory that uses given writer for log output (unadorned). +func ToWriter(w io.Writer) LoggerFactory { + return zap.New(zapcore.NewCore( + NewStdConsoleEncoder(StdConsoleEncoderConfig{}), + zapcore.AddSync(w), zap.DebugLevel), zap.WithClock(Clock())).Sugar().Named +} diff --git a/pkg/logging/logging_test.go b/pkg/logging/logging_test.go new file mode 100644 index 0000000..037ff64 --- /dev/null +++ b/pkg/logging/logging_test.go @@ -0,0 +1,154 @@ +package logging_test + +import ( + "bytes" + "context" + "fmt" + "testing" + + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + + "github.com/apecloud/datasafed/pkg/logging" +) + +// Printf returns a logger that uses given printf-style function to print log output. +func Printf(printf func(msg string, args ...interface{}), prefix string) *zap.SugaredLogger { + return PrintfLevel(printf, prefix, zapcore.DebugLevel) +} + +// PrintfLevel returns a logger that uses given printf-style function to print log output for logs of a given level or above. +func PrintfLevel(printf func(msg string, args ...interface{}), prefix string, level zapcore.Level) *zap.SugaredLogger { + writer := printfWriter{printf, prefix} + + return zap.New( + zapcore.NewCore( + logging.NewStdConsoleEncoder(logging.StdConsoleEncoderConfig{}), + writer, + level, + ), + ).Sugar() +} + +// PrintfFactory returns LoggerForModuleFunc that uses given printf-style function to print log output. +func PrintfFactory(printf func(msg string, args ...interface{})) logging.LoggerFactory { + return func(module string) *zap.SugaredLogger { + return Printf(printf, "["+module+"] ") + } +} + +type printfWriter struct { + printf func(msg string, args ...interface{}) + prefix string +} + +func (w printfWriter) Write(p []byte) (int, error) { + n := len(p) + + w.printf("%s%s", w.prefix, bytes.TrimRight(p, "\n")) + + return n, nil +} + +func (w printfWriter) Sync() error { + return nil +} + +func TestBroadcast(t *testing.T) { + var lines []string + + l0 := Printf(func(msg string, args ...interface{}) { + lines = append(lines, fmt.Sprintf(msg, args...)) + }, "[first] ") + + l1 := Printf(func(msg string, args ...interface{}) { + lines = append(lines, fmt.Sprintf(msg, args...)) + }, "[second] ") + + l := logging.Broadcast(l0, l1) + l.Debugf("A") + l.Debugw("S", "b", 123) + l.Infof("B") + l.Errorf("C") + l.Warnf("W") + + require.Equal(t, []string{ + "[first] A", + "[second] A", + "[first] S\t{\"b\":123}", + "[second] S\t{\"b\":123}", + "[first] B", + "[second] B", + "[first] C", + "[second] C", + "[first] W", + "[second] W", + }, lines) +} + +func TestWriter(t *testing.T) { + var buf bytes.Buffer + + l := logging.ToWriter(&buf)("module1") + l.Debugf("A") + l.Debugw("S", "b", 123) + l.Infof("B") + l.Errorf("C") + l.Warnf("W") + + require.Equal(t, "A\nS\t{\"b\":123}\nB\nC\nW\n", buf.String()) +} + +func TestNullWriterModule(t *testing.T) { + l := logging.Module("mod1")(context.Background()) + + l.Debugf("A") + l.Debugw("S", "b", 123) + l.Infof("B") + l.Errorf("C") + l.Warnf("W") +} + +func TestNonNullWriterModule(t *testing.T) { + var buf bytes.Buffer + + ctx := logging.WithLogger(context.Background(), logging.ToWriter(&buf)) + l := logging.Module("mod1")(ctx) + + l.Debugf("A") + l.Debugw("S", "b", 123) + l.Infof("B") + l.Errorf("C") + l.Warnf("W") + + require.Equal(t, "A\nS\t{\"b\":123}\nB\nC\nW\n", buf.String()) +} + +func TestWithAdditionalLogger(t *testing.T) { + var buf, buf2 bytes.Buffer + + ctx := logging.WithLogger(context.Background(), logging.ToWriter(&buf)) + ctx = logging.WithAdditionalLogger(ctx, logging.ToWriter(&buf2)) + l := logging.Module("mod1")(ctx) + + l.Debugf("A") + l.Debugw("S", "b", 123) + l.Infof("B") + l.Errorf("C") + l.Warnf("W") + + require.Equal(t, "A\nS\t{\"b\":123}\nB\nC\nW\n", buf.String()) + require.Equal(t, "A\nS\t{\"b\":123}\nB\nC\nW\n", buf2.String()) +} + +func BenchmarkLogger(b *testing.B) { + mod1 := logging.Module("mod1") + ctx := logging.WithLogger(context.Background(), PrintfFactory(b.Logf)) + + b.ResetTimer() + + for i := 0; i < b.N; i++ { + mod1(ctx) + } +} diff --git a/pkg/logging/null_logger.go b/pkg/logging/null_logger.go new file mode 100644 index 0000000..627aa76 --- /dev/null +++ b/pkg/logging/null_logger.go @@ -0,0 +1,12 @@ +package logging + +import "go.uber.org/zap" + +// NullLogger represents a singleton logger that discards all output. +// +//nolint:gochecknoglobals +var NullLogger = zap.NewNop().Sugar() + +func getNullLogger(_ string) Logger { + return NullLogger +} diff --git a/pkg/logging/zaplogutil.go b/pkg/logging/zaplogutil.go new file mode 100644 index 0000000..a7fa7af --- /dev/null +++ b/pkg/logging/zaplogutil.go @@ -0,0 +1,139 @@ +package logging + +import ( + "time" + + "go.uber.org/zap/buffer" + "go.uber.org/zap/zapcore" +) + +// PreciseLayout is a variant of time.RFC3339Nano but with microsecond precision +// and trailing zeroes. +const PreciseLayout = "2006-01-02T15:04:05.000000Z07:00" + +// PreciseTimeEncoder encodes the time as RFC3389 with 6 digits of sub-second precision. +func PreciseTimeEncoder() zapcore.TimeEncoder { + return zapcore.TimeEncoderOfLayout(PreciseLayout) +} + +type theClock struct{} + +func (c theClock) Now() time.Time { return time.Now() } +func (c theClock) NewTicker(d time.Duration) *time.Ticker { return time.NewTicker(d) } + +// Clock is an implementation of zapcore.Clock that uses clock.Now(). +func Clock() zapcore.Clock { + return theClock{} +} + +// TimezoneAdjust returns zapcore.TimeEncoder that adjusts the time to either UTC or local time before logging. +func TimezoneAdjust(inner zapcore.TimeEncoder, isLocal bool) zapcore.TimeEncoder { + if isLocal { + return func(t time.Time, pae zapcore.PrimitiveArrayEncoder) { + inner(t.Local(), pae) + } + } + + return func(t time.Time, pae zapcore.PrimitiveArrayEncoder) { + inner(t.UTC(), pae) + } +} + +// NewStdConsoleEncoder returns standardized console encoder which is optimized +// for performance. +func NewStdConsoleEncoder(ec StdConsoleEncoderConfig) zapcore.Encoder { + return &stdConsoleEncoder{zapcore.NewJSONEncoder(zapcore.EncoderConfig{ + EncodeTime: zapcore.ISO8601TimeEncoder, + EncodeDuration: zapcore.StringDurationEncoder, + SkipLineEnding: true, + }), ec} +} + +// StdConsoleEncoderConfig provides configurationfor NewStdConsoleEncoder. +type StdConsoleEncoderConfig struct { + TimeLayout string + LocalTime bool + EmitLoggerName bool + EmitLogLevel bool + DoNotEmitInfoLevel bool + ColoredLogLevel bool +} + +//nolint:gochecknoglobals +var bufPool = buffer.NewPool() + +type stdConsoleEncoder struct { + zapcore.Encoder // inherit JSON encoder + + StdConsoleEncoderConfig +} + +func (c *stdConsoleEncoder) Clone() zapcore.Encoder { + return &stdConsoleEncoder{ + c.Encoder.Clone(), + c.StdConsoleEncoderConfig, + } +} + +func (c *stdConsoleEncoder) EncodeEntry(ent zapcore.Entry, fields []zapcore.Field) (*buffer.Buffer, error) { + line := bufPool.Get() + + separator := "" + + if c.TimeLayout != "" { + if c.LocalTime { + line.AppendTime(ent.Time.Local(), c.TimeLayout) + } else { + line.AppendTime(ent.Time.UTC(), c.TimeLayout) + } + + separator = " " + } + + if c.EmitLogLevel { + line.AppendString(separator) + + if ent.Level != zapcore.InfoLevel || !c.DoNotEmitInfoLevel { + if c.ColoredLogLevel { + switch ent.Level { + case zapcore.DebugLevel: + line.AppendString("\x1b[35m") // magenta + case zapcore.WarnLevel: + line.AppendString("\x1b[33m") // yellow + default: + line.AppendString("\x1b[31m") // red + } + + line.AppendString(ent.Level.CapitalString()) + line.AppendString("\x1b[0m") + } else { + line.AppendString(ent.Level.CapitalString()) + } + + separator = " " + } + } + + if ent.LoggerName != "" && c.EmitLoggerName { + line.AppendString(separator) + line.AppendString(ent.LoggerName) + + separator = " " + } + + line.AppendString(separator) + line.AppendString(ent.Message) + + if line2, err := c.Encoder.EncodeEntry(ent, fields); err == nil { + if line2.Len() > 2 { //nolint:gomnd + line.AppendString("\t") + line.AppendString(line2.String()) + } + + line2.Free() + } + + line.AppendString("\n") + + return line, nil +}