From 1e783881b55f0de532f85f2154936a88a56f0d50 Mon Sep 17 00:00:00 2001 From: Stefano Scafiti Date: Tue, 10 Sep 2024 10:34:46 +0200 Subject: [PATCH] chore(embedded/logging): improve file base logging. - Implement size and age based log rotation - Add a flag to enable lof of accesses Signed-off-by: Stefano Scafiti --- cmd/immudb/command/cmd_test.go | 4 +- cmd/immudb/command/init.go | 10 +- cmd/immudb/command/parse_options.go | 9 + cmd/immudb/command/root.go | 14 +- embedded/logger/file.go | 8 +- embedded/logger/json.go | 53 +--- embedded/logger/log_file_writer.go | 184 +++++++++++++ embedded/logger/log_file_writer_test.go | 285 +++++++++++++++++++++ embedded/logger/logger.go | 41 ++- embedded/logger/logger_test.go | 31 +-- embedded/logger/simple.go | 5 + pkg/integration/client_test.go | 3 +- pkg/server/access_log_interceptor.go | 48 ++++ pkg/server/access_log_interceptor_test.go | 68 +++++ pkg/server/corruption_checker_test.go | 8 +- pkg/server/options.go | 32 ++- pkg/server/request_metadata_interceptor.go | 2 +- pkg/server/server.go | 5 +- pkg/server/server_test.go | 12 +- pkg/server/types.go | 8 +- 20 files changed, 730 insertions(+), 100 deletions(-) create mode 100644 embedded/logger/log_file_writer.go create mode 100644 embedded/logger/log_file_writer_test.go create mode 100644 pkg/server/access_log_interceptor.go create mode 100644 pkg/server/access_log_interceptor_test.go diff --git a/cmd/immudb/command/cmd_test.go b/cmd/immudb/command/cmd_test.go index d945cdf889..2354dbae65 100644 --- a/cmd/immudb/command/cmd_test.go +++ b/cmd/immudb/command/cmd_test.go @@ -18,7 +18,6 @@ package immudb import ( "bytes" - "path/filepath" "testing" "github.com/stretchr/testify/require" @@ -228,7 +227,8 @@ func TestImmudbLogFile(t *testing.T) { cmd.Flags().StringVar(&config, "config", "", "test") setupDefaults(server.DefaultOptions()) - viper.Set("logfile", filepath.Join(t.TempDir(), "override")) + viper.Set("dir", t.TempDir()) + viper.Set("logfile", "override") cl := Commandline{} diff --git a/cmd/immudb/command/init.go b/cmd/immudb/command/init.go index 32726117a5..92f58c46f9 100644 --- a/cmd/immudb/command/init.go +++ b/cmd/immudb/command/init.go @@ -48,8 +48,12 @@ func (cl *Commandline) setupFlags(cmd *cobra.Command, options *server.Options) { cmd.PersistentFlags().StringVar(&cl.config.CfgFn, "config", "", "config file (default path are configs or $HOME. Default filename is immudb.toml)") cmd.Flags().String("pidfile", options.Pidfile, "pid path with filename e.g. /var/run/immudb.pid") - cmd.Flags().String("logfile", options.Logfile, "log path with filename e.g. /tmp/immudb/immudb.log") + cmd.Flags().String("logdir", options.LogDir, "log path base dir /tmp/immudb/immulog") + cmd.Flags().String("logfile", options.Logfile, "filename e.g. immudb.log") cmd.Flags().String("logformat", options.LogFormat, "log format e.g. text/json") + cmd.Flags().Int("log-rotation-size", options.LogRotationSize, "maximum size a log segment can reach before being rotated") + cmd.Flags().Duration("log-rotation-age", options.LogRotationAge, "maximum duration (age) of a log segment before it is rotated") + cmd.Flags().Bool("log-access", options.LogAccess, "log incoming requests information (username, IP, etc...)") cmd.Flags().BoolP("mtls", "m", false, "enable mutual tls") cmd.Flags().BoolP("auth", "s", false, "enable auth") cmd.Flags().Int("max-recv-msg-size", options.MaxRecvMsgSize, "max message size in bytes the server can receive") @@ -118,6 +122,10 @@ func setupDefaults(options *server.Options) { viper.SetDefault("replica", false) viper.SetDefault("pidfile", options.Pidfile) viper.SetDefault("logfile", options.Logfile) + viper.SetDefault("logdir", options.LogDir) + viper.SetDefault("log-rotation-size", options.LogRotationSize) + viper.SetDefault("log-rotation-age", options.LogRotationAge) + viper.SetDefault("log-access", options.LogAccess) viper.SetDefault("mtls", false) viper.SetDefault("auth", options.GetAuth()) viper.SetDefault("max-recv-msg-size", options.MaxRecvMsgSize) diff --git a/cmd/immudb/command/parse_options.go b/cmd/immudb/command/parse_options.go index 54fec1195a..63b6935ea0 100644 --- a/cmd/immudb/command/parse_options.go +++ b/cmd/immudb/command/parse_options.go @@ -51,7 +51,12 @@ func parseOptions() (options *server.Options, err error) { } pidfile := viper.GetString("pidfile") + + logdir := viper.GetString("logdir") logfile := viper.GetString("logfile") + logRotationSize := viper.GetInt("log-rotation-size") + logRotationAge := viper.GetDuration("log-rotation-age") + logAccess := viper.GetBool("log-access") logFormat := viper.GetString("logformat") mtls := viper.GetBool("mtls") @@ -131,7 +136,11 @@ func parseOptions() (options *server.Options, err error) { WithAddress(address). WithReplicationOptions(replicationOptions). WithPidfile(pidfile). + WithLogDir(logdir). WithLogfile(logfile). + WithLogRotationSize(logRotationSize). + WithLogRotationAge(logRotationAge). + WithLogAccess(logAccess). WithTLS(tlsConfig). WithAuth(auth). WithMaxRecvMsgSize(maxRecvMsgSize). diff --git a/cmd/immudb/command/root.go b/cmd/immudb/command/root.go index 3063e5ba1c..f4f6d883c7 100644 --- a/cmd/immudb/command/root.go +++ b/cmd/immudb/command/root.go @@ -17,6 +17,8 @@ limitations under the License. package immudb import ( + "path/filepath" + c "github.com/codenotary/immudb/cmd/helper" "github.com/codenotary/immudb/embedded/logger" "github.com/codenotary/immudb/pkg/server" @@ -68,10 +70,14 @@ func (cl *Commandline) Immudb(immudbServer server.ImmuServerIf) func(*cobra.Comm // initialize logger for immudb ilogger, err := logger.NewLogger(&logger.Options{ - Name: "immudb", - LogFormat: options.LogFormat, - LogFile: options.Logfile, - Level: logger.LogLevelFromEnvironment(), + Name: "immudb", + LogFormat: options.LogFormat, + LogDir: filepath.Join(options.Dir, options.LogDir), + LogFile: options.Logfile, + LogRotationSize: options.LogRotationSize, + LogRotationAge: options.LogRotationAge, + LogFileTimeFormat: logger.LogFileFormat, + Level: logger.LogLevelFromEnvironment(), }) if err != nil { c.QuitToStdErr(err) diff --git a/embedded/logger/file.go b/embedded/logger/file.go index 6cf7ec69b7..0b66e24e43 100644 --- a/embedded/logger/file.go +++ b/embedded/logger/file.go @@ -23,14 +23,14 @@ import ( "path/filepath" ) -// FileLogger ... +// Deprecated: FileLogger is deprecated and will be removed in a future release. type FileLogger struct { Logger *log.Logger LogLevel LogLevel out *os.File } -// NewFileLogger ... +// Deprecated: use method NewLogger instead. func NewFileLogger(name string, file string) (logger Logger, out *os.File, err error) { out, err = setup(file) if err != nil { @@ -60,12 +60,12 @@ func NewFileLoggerWithLevel(name string, file string, level LogLevel) (logger Lo func setup(file string) (out *os.File, err error) { if _, err = os.Stat(filepath.Dir(file)); os.IsNotExist(err) { if err = os.Mkdir(filepath.Dir(file), os.FileMode(0755)); err != nil { - return nil, errors.New("Unable to create log folder") + return nil, errors.New("unable to create log folder") } } out, err = os.OpenFile(file, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666) if err != nil { - return out, errors.New("Unable to create log file") + return out, errors.New("unable to create log file") } return out, err } diff --git a/embedded/logger/json.go b/embedded/logger/json.go index 1b4b27951c..525bbcffe6 100644 --- a/embedded/logger/json.go +++ b/embedded/logger/json.go @@ -17,7 +17,6 @@ limitations under the License. package logger import ( - "bytes" "encoding" "encoding/json" "fmt" @@ -61,7 +60,7 @@ type JsonLogger struct { timeFnc TimeFunc mutex sync.Mutex - writer *writer + writer io.Writer level int32 } @@ -77,19 +76,11 @@ func NewJSONLogger(opts *Options) (*JsonLogger, error) { output = defaultOutput } - if opts.LogFile != "" { - out, err := setup(opts.LogFile) - if err != nil { - return nil, err - } - output = out - } - l := &JsonLogger{ name: opts.Name, timeFormat: DefaultTimeFormat, timeFnc: time.Now, - writer: newWriter(output), + writer: output, } if opts.TimeFnc != nil { @@ -121,14 +112,12 @@ func (l *JsonLogger) log(name string, level LogLevel, msg string, args ...interf t := l.timeFnc() l.logJSON(t, name, level, msg, args...) - - l.writer.Flush() } func (l *JsonLogger) logJSON(t time.Time, name string, level LogLevel, msg string, args ...interface{}) { vals := l.getVals(t, name, level, msg) - if args != nil && len(args) > 0 { + if len(args) > 0 { for i := 0; i < len(args); i = i + 2 { val := args[i+1] switch sv := val.(type) { @@ -243,38 +232,8 @@ func (i *JsonLogger) Name() string { // Close the logger func (i *JsonLogger) Close() error { - return i.writer.Close() -} - -type writer struct { - b bytes.Buffer - out io.Writer -} - -func newWriter(w io.Writer) *writer { - return &writer{out: w} -} - -func (w *writer) Flush() (err error) { - var unwritten = w.b.Bytes() - _, err = w.out.Write(unwritten) - w.b.Reset() - return err -} - -func (w *writer) Write(p []byte) (int, error) { - return w.b.Write(p) -} - -func (w *writer) Close() error { - switch t := w.out.(type) { - case *os.File: - err := w.Flush() - if err != nil { - return err - } - return t.Close() - default: - return w.Flush() + if wc, ok := i.writer.(io.Closer); ok { + return wc.Close() } + return nil } diff --git a/embedded/logger/log_file_writer.go b/embedded/logger/log_file_writer.go new file mode 100644 index 0000000000..4e6e06802d --- /dev/null +++ b/embedded/logger/log_file_writer.go @@ -0,0 +1,184 @@ +/* +Copyright 2024 Codenotary Inc. All rights reserved. + +SPDX-License-Identifier: BUSL-1.1 +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + https://mariadb.com/bsl11/ + +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 logger + +import ( + "errors" + "fmt" + "io" + "os" + "path/filepath" + "strings" + "time" +) + +func createLogFileWriter(opts *Options) (io.Writer, error) { + if opts.LogDir != "" { + if err := os.MkdirAll(opts.LogDir, os.ModePerm); err != nil && !errors.Is(err, os.ErrExist) { + return nil, err + } + } + + if opts.LogRotationAge > 0 && opts.LogRotationAge < logRotationAgeMin { + return nil, fmt.Errorf("log rotation age must be greater than %s", logRotationAgeMin.String()) + } + + timeFunc := opts.TimeFnc + if timeFunc == nil { + timeFunc = func() time.Time { + return time.Now() + } + } + + lf := &logFileWriter{ + timeFunc: timeFunc, + timeFormat: opts.LogFileTimeFormat, + dir: opts.LogDir, + fileName: opts.LogFile, + rotationSize: opts.LogRotationSize, + rotationAge: opts.LogRotationAge, + currSegmentSize: 0, + } + err := lf.rotate(lf.currAge()) + return lf, err +} + +var _ io.Closer = (*logFileWriter)(nil) + +type logFileWriter struct { + currSegment *os.File + + timeFunc TimeFunc + timeFormat string + + dir string + fileName string + + rotationSize int + rotationAge time.Duration + + currentSegmentAgeNum int64 + currSegmentSize int + nextSeqNum int +} + +func (bf *logFileWriter) Write(buf []byte) (int, error) { + age := bf.currAge() + if bf.shouldRotate(len(buf), age) { + if err := bf.rotate(age); err != nil { + return -1, err + } + } + + n, err := bf.currSegment.Write(buf) + if err == nil { + bf.currSegmentSize += len(buf) + } + return n, err +} + +func (bf *logFileWriter) shouldRotate(nBytes int, ageNum int64) bool { + if bf.rotationAge == 0 && bf.rotationSize == 0 { + return false + } + + if bf.rotationSize > 0 && bf.currSegmentSize+int(nBytes) > bf.rotationSize { + return true + } + + if bf.rotationAge > 0 && int64(ageNum) > bf.currentSegmentAgeNum { + return true + } + return false +} + +func (bf *logFileWriter) rotate(age int64) error { + if err := bf.Close(); err != nil { + return err + } + + bf.currSegmentSize = 0 + if bf.rotationAge > 0 { + bf.currentSegmentAgeNum = age + } + + name, err := bf.getNextSegmentName() + if err != nil { + return err + } + + logFile, err := os.Create(name) + if err != nil { + return err + } + + bf.currSegment = logFile + return nil +} + +func (bf *logFileWriter) getNextSegmentName() (string, error) { + num := bf.nextSeqNum + name := bf.segmentName() + _, err := os.Stat(name) + for err == nil { + num++ + _, err = os.Stat(fmt.Sprintf("%s.%04d", name, num)) + } + if !errors.Is(err, os.ErrNotExist) { + return "", err + } + + // NOTE: Without specifying a time format, the same file names will be generated during each rotation. + if bf.timeFormat == "" { + bf.nextSeqNum = num + } + + if num > 0 { + return fmt.Sprintf("%s.%04d", name, num), nil + } + return name, nil +} + +func (bf *logFileWriter) segmentName() string { + if bf.timeFormat == "" || bf.rotationAge == 0 { + return filepath.Join(bf.dir, bf.fileName) + } + + ext := filepath.Ext(bf.fileName) + t := time.Unix(0, bf.currentSegmentAgeNum*bf.rotationAge.Nanoseconds()) + + name := fmt.Sprintf("%s_%s%s", strings.TrimSuffix(bf.fileName, ext), t.Format(bf.timeFormat), ext) + return filepath.Join(bf.dir, name) +} + +func (bf *logFileWriter) currAge() int64 { + if bf.rotationAge == 0 { + return 0 + } + return bf.timeFunc().UnixNano() / bf.rotationAge.Nanoseconds() +} + +func (bf *logFileWriter) Close() error { + if bf.currSegment == nil { + return nil + } + + if err := bf.currSegment.Sync(); err != nil { + return err + } + return bf.currSegment.Close() +} diff --git a/embedded/logger/log_file_writer_test.go b/embedded/logger/log_file_writer_test.go new file mode 100644 index 0000000000..274499f955 --- /dev/null +++ b/embedded/logger/log_file_writer_test.go @@ -0,0 +1,285 @@ +/* +Copyright 2024 Codenotary Inc. All rights reserved. + +SPDX-License-Identifier: BUSL-1.1 +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + https://mariadb.com/bsl11/ + +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 logger + +import ( + "bufio" + "fmt" + "os" + "path" + "path/filepath" + "sort" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +func TestLogFileIsRotatedOnInit(t *testing.T) { + tempDir := t.TempDir() + + today := time.Now().Truncate(time.Hour * 24) + + opts := &Options{ + Name: "immudb", + LogFormat: LogFormatJSON, + Level: LogDebug, + LogDir: tempDir, + LogFile: "immudb.log", + TimeFormat: LogFileFormat, + TimeFnc: func() time.Time { + return today + }, + } + + logger, err := NewLogger(opts) + require.NoError(t, err) + + files, err := readFiles(tempDir, "immudb") + require.NoError(t, err) + require.Len(t, files, 1) + require.Equal(t, "immudb.log", files[0]) + + err = logger.Close() + require.NoError(t, err) + + logger, err = NewLogger(opts) + require.NoError(t, err) + defer logger.Close() + + files, err = readFiles(tempDir, "immudb") + require.NoError(t, err) + require.Len(t, files, 2) + require.Equal(t, []string{"immudb.log", "immudb.log.0001"}, files) +} + +type mockWriter struct { + nBytes int + nCalls int +} + +func (w *mockWriter) Write(buf []byte) (int, error) { + w.nBytes += len(buf) + w.nCalls++ + return len(buf), nil +} + +func TestLogAreSentToOutput(t *testing.T) { + mw := &mockWriter{} + + logger, err := NewLogger(&Options{ + Name: "immudb", + LogFormat: LogFormatJSON, + Output: mw, + Level: LogDebug, + }) + require.NoError(t, err) + defer logger.Close() + + nLogs := 100 + for i := 0; i < nLogs; i++ { + logger.Errorf("test log %d", i) + } + require.Equal(t, mw.nCalls, nLogs) +} + +func TestLoggerFileWithRotationDisabled(t *testing.T) { + tempDir := t.TempDir() + + logger, err := NewLogger(&Options{ + Name: "immudb", + LogFormat: LogFormatJSON, + Level: LogDebug, + LogDir: tempDir, + LogFile: "immudb.log", + TimeFnc: func() time.Time { + return time.Now() + }, + }) + require.NoError(t, err) + defer logger.Close() + + nLogs := 100 + for i := 0; i < nLogs; i++ { + logger.Errorf("test log %d", i) + } + + err = logger.Close() + require.NoError(t, err) + + entries, err := os.ReadDir(tempDir) + require.NoError(t, err) + require.Len(t, entries, 1) + require.Equal(t, "immudb.log", entries[0].Name()) + + f, err := os.Open(filepath.Join(tempDir, "immudb.log")) + require.NoError(t, err) + + sc := bufio.NewScanner(f) + for sc.Scan() { + require.Contains(t, sc.Text(), "test log") + } + require.NoError(t, sc.Err()) +} + +func TestLoggerFileAgeRotation(t *testing.T) { + tempDir := t.TempDir() + + age := time.Hour * 24 + i := 0 + now := time.Now().Truncate(age) + + logger, err := NewLogger(&Options{ + Name: "immudb", + LogFormat: LogFormatText, + Level: LogDebug, + LogDir: tempDir, + LogFile: "immudb.log", + LogRotationSize: 1024 * 1024, + LogRotationAge: time.Hour * 24, + TimeFnc: func() time.Time { + t := now.Add(age * time.Duration(i)) + i++ + return t + }, + }) + require.NoError(t, err) + defer logger.Close() + + nLogs := 100 + for i := 0; i < nLogs; i++ { + logger.Errorf("this is a test") + } + require.Equal(t, nLogs+1, i) + + entries, err := os.ReadDir(tempDir) + require.NoError(t, err) + require.Len(t, entries, nLogs+1) + + files, err := readFiles(tempDir, "immudb.log") + require.NoError(t, err) + require.Len(t, files, nLogs+1) + + require.Equal(t, files[0], "immudb.log") + for i := 1; i < len(files); i++ { + require.Equal(t, fmt.Sprintf("immudb.log.%04d", i), files[i]) + } +} + +func TestLoggerFileAgeRotationWithTimeFormat(t *testing.T) { + tempDir := t.TempDir() + + age := time.Hour * 24 + i := 0 + now := time.Now().Truncate(age) + + logger, err := NewLogger(&Options{ + Name: "immudb", + LogFormat: LogFormatText, + LogFileTimeFormat: LogFileFormat, + Level: LogDebug, + LogDir: tempDir, + LogFile: "immudb.log", + LogRotationSize: 1024 * 1024, + LogRotationAge: time.Hour * 24, + TimeFnc: func() time.Time { + t := now.Add(age * time.Duration(i)) + i++ + return t + }, + }) + require.NoError(t, err) + defer logger.Close() + + nLogs := 100 + for i := 0; i < nLogs; i++ { + logger.Errorf("this is a test") + } + require.Equal(t, nLogs+1, i) + + files, err := readFiles(tempDir, "immudb") + require.NoError(t, err) + require.Len(t, files, nLogs+1) + + for n, f := range files { + name := strings.TrimSuffix(f, path.Ext(f)) + idx := strings.LastIndex(name, "_") + require.GreaterOrEqual(t, idx, 0) + + segmentAge := name[idx+1:] + ageTime, err := time.Parse(LogFileFormat, segmentAge) + require.NoError(t, err) + require.Equal(t, ageTime.UTC(), now.Add(age*time.Duration(n)).UTC()) + } +} + +func TestLoggerFileSizeRotation(t *testing.T) { + tempDir := t.TempDir() + + logger, err := NewLogger(&Options{ + Name: "immudb", + LogFormat: LogFormatText, + Level: LogDebug, + LogDir: tempDir, + LogFile: "immudb.log", + LogRotationSize: 100, + LogRotationAge: time.Hour * 24, + }) + require.NoError(t, err) + + nLogs := 100 + for i := 0; i < nLogs; i++ { + logger.Errorf("this is a test") + } + + err = logger.Close() + require.NoError(t, err) + + files, err := readFiles(tempDir, "immudb.log") + require.NoError(t, err) + require.NotEmpty(t, files) + + for _, fname := range files { + finfo, err := os.Stat(filepath.Join(tempDir, fname)) + require.NoError(t, err) + require.LessOrEqual(t, finfo.Size(), int64(100)) + } +} + +func readFiles(dir, prefix string) ([]string, error) { + entries, err := os.ReadDir(dir) + if err != nil { + return nil, err + } + + files := make([]string, 0) + for _, e := range entries { + if e.IsDir() { + continue + } + + if strings.HasPrefix(e.Name(), prefix) { + files = append(files, e.Name()) + } + } + + sort.Slice(files, func(i, j int) bool { + return files[i] < files[j] + }) + return files, nil +} diff --git a/embedded/logger/logger.go b/embedded/logger/logger.go index 7c601a3443..3abd952671 100644 --- a/embedded/logger/logger.go +++ b/embedded/logger/logger.go @@ -35,6 +35,11 @@ var ( } ) +const ( + LogFileFormat = time.RFC3339 + logRotationAgeMin = time.Minute +) + // LogLevel ... type LogLevel int8 @@ -93,22 +98,46 @@ type ( // The format in which logs will be formatted. (eg: text/json) LogFormat string + // The directory logs will be stored to. + LogDir string + // The file to write to. LogFile string + + // The time format of different log segments. + LogFileTimeFormat string + + // The maximum size a log segment can reach before being rotated. + LogRotationSize int + + // The maximum duration (age) of a log segment before it is rotated. + LogRotationAge time.Duration } ) // NewLogger is a factory for selecting a logger based on options func NewLogger(opts *Options) (logger Logger, err error) { + out := opts.Output + if out == nil { + out = os.Stderr + } + + if opts.LogFile != "" { + w, err := createLogFileWriter(opts) + if err != nil { + return nil, err + } + out = w + } + switch opts.LogFormat { case LogFormatJSON: - return NewJSONLogger(opts) + optsCopy := *opts + optsCopy.Output = out + + return NewJSONLogger(&optsCopy) case LogFormatText: - if opts.LogFile != "" { - logger, _, err = NewFileLogger(opts.Name, opts.LogFile) - return logger, err - } - return NewSimpleLogger(opts.Name, defaultOutput), nil + return NewSimpleLogger(opts.Name, out), nil default: return nil, ErrInvalidLoggerType } diff --git a/embedded/logger/logger_test.go b/embedded/logger/logger_test.go index f7cd0217dd..355e6d3cb2 100644 --- a/embedded/logger/logger_test.go +++ b/embedded/logger/logger_test.go @@ -72,44 +72,37 @@ func TestNewLogger(t *testing.T) { } func TestNewLoggerWithFile(t *testing.T) { - type args struct { - opts *Options - } tests := []struct { name string - args args + opts *Options wantLoggerType Logger wantErr bool }{ { name: "with json logger", - args: args{ - opts: &Options{ - Name: "foo", - LogFormat: "json", - LogFile: filepath.Join(t.TempDir(), "log_json.log"), - }, + opts: &Options{ + Name: "foo", + LogFormat: "json", + LogFile: filepath.Join(t.TempDir(), "log_json.log"), }, wantLoggerType: &JsonLogger{}, wantErr: false, }, { name: "with text logger", - args: args{ - opts: &Options{ - Name: "foo", - LogFormat: LogFormatText, - LogFile: filepath.Join(t.TempDir(), "log_text.log"), - }, + opts: &Options{ + Name: "foo", + LogFormat: LogFormatText, + LogFile: filepath.Join(t.TempDir(), "log_text.log"), }, - wantLoggerType: &FileLogger{}, + wantLoggerType: &SimpleLogger{}, wantErr: false, }, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - gotLogger, err := NewLogger(tt.args.opts) - defer os.RemoveAll(tt.args.opts.LogFile) + gotLogger, err := NewLogger(tt.opts) + defer os.RemoveAll(tt.opts.LogFile) if (err != nil) != tt.wantErr { t.Errorf("NewLogger() error = %v, wantErr %v", err, tt.wantErr) return diff --git a/embedded/logger/simple.go b/embedded/logger/simple.go index 0ed57bca6b..ca75fd1166 100644 --- a/embedded/logger/simple.go +++ b/embedded/logger/simple.go @@ -23,6 +23,7 @@ import ( // SimpleLogger ... type SimpleLogger struct { + Out io.Writer Logger *log.Logger LogLevel LogLevel } @@ -30,6 +31,7 @@ type SimpleLogger struct { // NewSimpleLogger ... func NewSimpleLogger(name string, out io.Writer) Logger { return &SimpleLogger{ + Out: out, Logger: log.New(out, name+" ", log.LstdFlags), LogLevel: LogLevelFromEnvironment(), } @@ -73,5 +75,8 @@ func (l *SimpleLogger) Debugf(f string, v ...interface{}) { // Close the logger ... func (l *SimpleLogger) Close() error { + if wc, ok := l.Out.(io.Closer); ok { + return wc.Close() + } return nil } diff --git a/pkg/integration/client_test.go b/pkg/integration/client_test.go index ab01efbb5a..e0d88bb783 100644 --- a/pkg/integration/client_test.go +++ b/pkg/integration/client_test.go @@ -70,8 +70,7 @@ func setupTestServerAndClient(t *testing.T) (*servertest.BufconnServer, ic.ImmuC WithDir(filepath.Join(t.TempDir(), "data")). WithAuth(true). WithLogRequestMetadata(true). - WithSigningKey("./../../test/signer/ec1.key"), - ) + WithSigningKey("./../../test/signer/ec1.key")) bs.Start() t.Cleanup(func() { bs.Stop() }) diff --git a/pkg/server/access_log_interceptor.go b/pkg/server/access_log_interceptor.go new file mode 100644 index 0000000000..e0a77d57ef --- /dev/null +++ b/pkg/server/access_log_interceptor.go @@ -0,0 +1,48 @@ +package server + +import ( + "context" + "time" + + "google.golang.org/grpc" +) + +func (s *ImmuServer) AccessLogStreamInterceptor(srv interface{}, ss grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error { + start := time.Now() + + err := handler(srv, ss) + + _ = s.logAccess(ss.Context(), info.FullMethod, time.Since(start), err) + return err +} + +func (s *ImmuServer) AccessLogInterceptor(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { + start := time.Now() + + res, err := handler(ctx, req) + + _ = s.logAccess(ctx, info.FullMethod, time.Since(start), err) + return res, err +} + +func (s *ImmuServer) logAccess(ctx context.Context, method string, rpcDuration time.Duration, rpcErr error) error { + if !s.Options.LogAccess { + return nil + } + + var username string + + _, user, err := s.getLoggedInUserdataFromCtx(ctx) + if err == nil { + username = user.Username + } + + ip := ipAddrFromContext(ctx) + + if rpcErr == nil { + s.Logger.Infof("user=%s,ip=%s,method=%s,duration=%s", username, ip, method, rpcDuration.String()) + } else { + s.Logger.Infof("user=%s,ip=%s,method=%s,duration=%s,error=%s", username, ip, method, rpcDuration.String(), rpcErr) + } + return nil +} diff --git a/pkg/server/access_log_interceptor_test.go b/pkg/server/access_log_interceptor_test.go new file mode 100644 index 0000000000..36a8036366 --- /dev/null +++ b/pkg/server/access_log_interceptor_test.go @@ -0,0 +1,68 @@ +package server + +import ( + "context" + "fmt" + "net" + "testing" + + "github.com/codenotary/immudb/pkg/auth" + "github.com/stretchr/testify/require" + "google.golang.org/grpc" + "google.golang.org/grpc/peer" +) + +func TestAccessLogInterceptors(t *testing.T) { + opts := DefaultOptions(). + WithDir(t.TempDir()). + WithLogAccess(true). + WithMetricsServer(false). + WithAdminPassword(auth.SysAdminPassword) + + s := DefaultServer().WithOptions(opts).(*ImmuServer) + defer s.CloseDatabases() + + logger := &mockLogger{captureLogs: true} + s.WithLogger(logger) + + err := s.Initialize() + require.NoError(t, err) + + ctx := peer.NewContext(context.Background(), &peer.Peer{Addr: &net.IPAddr{IP: net.IPv4(192, 168, 1, 1)}}) + + t.Run("unary interceptor", func(t *testing.T) { + called := false + _, err := s.AccessLogInterceptor(ctx, nil, &grpc.UnaryServerInfo{FullMethod: "testMethod"}, func(ctx context.Context, req interface{}) (interface{}, error) { + called = true + return nil, nil + }) + require.NoError(t, err) + + require.True(t, called) + require.NotEmpty(t, logger.logs) + + lastLine := logger.logs[len(logger.logs)-1] + require.Contains(t, lastLine, "ip=192.168.1.1") + require.Contains(t, lastLine, "user=,") + require.Contains(t, lastLine, "method=testMethod") + require.NotContains(t, lastLine, "error=") + }) + + t.Run("streaming interceptor", func(t *testing.T) { + called := false + err := s.AccessLogStreamInterceptor(nil, &mockServerStream{ctx: ctx}, &grpc.StreamServerInfo{FullMethod: "testMethod"}, func(srv interface{}, stream grpc.ServerStream) error { + called = true + return fmt.Errorf("test error") + }) + require.Error(t, err) + + require.True(t, called) + require.NotEmpty(t, logger.logs) + + lastLine := logger.logs[len(logger.logs)-1] + require.Contains(t, lastLine, "ip=192.168.1.1") + require.Contains(t, lastLine, "user=,") + require.Contains(t, lastLine, "method=testMethod") + require.Contains(t, lastLine, "error=test error") + }) +} diff --git a/pkg/server/corruption_checker_test.go b/pkg/server/corruption_checker_test.go index 91f1b2f667..5382e08d96 100644 --- a/pkg/server/corruption_checker_test.go +++ b/pkg/server/corruption_checker_test.go @@ -380,7 +380,8 @@ func makeDB(dir string) *badger.DB { */ type mockLogger struct { - lines []string + captureLogs bool + logs []string } func (l *mockLogger) Errorf(f string, v ...interface{}) { @@ -402,8 +403,9 @@ func (l *mockLogger) Debugf(f string, v ...interface{}) { func (l *mockLogger) Close() error { return nil } func (l *mockLogger) log(level, f string, v ...interface{}) { - line := level + ": " + fmt.Sprintf(f, v...) - l.lines = append(l.lines, line) + if l.captureLogs { + l.logs = append(l.logs, level+": "+fmt.Sprintf(f, v...)) + } } /* diff --git a/pkg/server/options.go b/pkg/server/options.go index aba34cdb1b..9de03c97ba 100644 --- a/pkg/server/options.go +++ b/pkg/server/options.go @@ -22,6 +22,7 @@ import ( "net" "strconv" "strings" + "time" "github.com/codenotary/immudb/embedded/logger" "github.com/codenotary/immudb/pkg/database" @@ -44,7 +45,11 @@ type Options struct { Port int Config string Pidfile string + LogDir string Logfile string + LogAccess bool + LogRotationSize int + LogRotationAge time.Duration AutoCert bool TLSConfig *tls.Config auth bool @@ -150,6 +155,8 @@ func DefaultOptions() *Options { GRPCReflectionServerEnabled: true, SwaggerUIEnabled: true, LogRequestMetadata: false, + LogDir: "immulog", + LogAccess: false, SharedIndexCacheSize: 1 << 27, // 128MB } } @@ -205,12 +212,36 @@ func (o *Options) WithPidfile(pidfile string) *Options { return o } +// WithLogDir sets LogDir +func (o *Options) WithLogDir(dir string) *Options { + o.LogDir = dir + return o +} + // WithLogfile sets logfile func (o *Options) WithLogfile(logfile string) *Options { o.Logfile = logfile return o } +// WithLogRotationSize sets the log rotation size +func (o *Options) WithLogRotationSize(size int) *Options { + o.LogRotationSize = size + return o +} + +// WithLogRotationAge sets the log rotation age +func (o *Options) WithLogRotationAge(age time.Duration) *Options { + o.LogRotationAge = age + return o +} + +// WithLogAccess sets the log rotation age +func (o *Options) WithLogAccess(enabled bool) *Options { + o.LogAccess = enabled + return o +} + func (o *Options) WithLogFormat(logFormat string) *Options { o.LogFormat = logFormat return o @@ -493,7 +524,6 @@ func (o *Options) WithPProf(pprof bool) *Options { func (o *Options) WithGRPCReflectionServerEnabled(enabled bool) *Options { o.GRPCReflectionServerEnabled = enabled - return o } diff --git a/pkg/server/request_metadata_interceptor.go b/pkg/server/request_metadata_interceptor.go index e9daa6e409..3c851e6bf5 100644 --- a/pkg/server/request_metadata_interceptor.go +++ b/pkg/server/request_metadata_interceptor.go @@ -71,7 +71,7 @@ func ipAddrFromContext(ctx context.Context) string { return "" } - addr := p.Addr.Network() + addr := p.Addr.String() i := strings.Index(addr, ":") if i < 0 { return addr diff --git a/pkg/server/server.go b/pkg/server/server.go index c9c4cf04e5..1a78c5d481 100644 --- a/pkg/server/server.go +++ b/pkg/server/server.go @@ -224,6 +224,7 @@ func (s *ImmuServer) Initialize() error { uis := []grpc.UnaryServerInterceptor{ ErrorMapper, // converts errors in gRPC ones. Need to be the first + s.AccessLogInterceptor, s.KeepAliveSessionInterceptor, uuidContext.UUIDContextSetter, grpc_prometheus.UnaryServerInterceptor, @@ -233,6 +234,7 @@ func (s *ImmuServer) Initialize() error { } sss := []grpc.StreamServerInterceptor{ ErrorMapperStream, // converts errors in gRPC ones. Need to be the first + s.AccessLogStreamInterceptor, s.KeepALiveSessionStreamInterceptor, uuidContext.UUIDStreamContextSetter, grpc_prometheus.StreamServerInterceptor, @@ -613,7 +615,8 @@ func (s *ImmuServer) loadUserDatabases(dataDir string, remoteStorage remotestora for _, f := range files { if !f.IsDir() || f.Name() == s.Options.GetSystemAdminDBName() || - f.Name() == s.Options.GetDefaultDBName() { + f.Name() == s.Options.GetDefaultDBName() || + f.Name() == s.Options.LogDir { continue } diff --git a/pkg/server/server_test.go b/pkg/server/server_test.go index 152c10ca11..683e8d4792 100644 --- a/pkg/server/server_test.go +++ b/pkg/server/server_test.go @@ -2150,16 +2150,16 @@ func TestUserIsAlertedToExpiredCerts(t *testing.T) { s, stop := testServer(opts) defer stop() - mockLogger := &mockLogger{} + mockLogger := &mockLogger{captureLogs: true} s.WithLogger(mockLogger) s.checkTLSCerts() - require.GreaterOrEqual(t, len(mockLogger.lines), 4) - require.Contains(t, mockLogger.lines[0], "is expired") - require.Contains(t, mockLogger.lines[1], "is about to expire") - require.Contains(t, mockLogger.lines[2], "tls config contains an invalid certificate") - require.Contains(t, mockLogger.lines[3], "could not parse certificate") + require.GreaterOrEqual(t, len(mockLogger.logs), 4) + require.Contains(t, mockLogger.logs[0], "is expired") + require.Contains(t, mockLogger.logs[1], "is about to expire") + require.Contains(t, mockLogger.logs[2], "tls config contains an invalid certificate") + require.Contains(t, mockLogger.logs[3], "could not parse certificate") } func makeCert(t *testing.T, dir, suffix string, expiration time.Duration) tls.Certificate { diff --git a/pkg/server/types.go b/pkg/server/types.go index 411a2a7596..19640ebcbf 100644 --- a/pkg/server/types.go +++ b/pkg/server/types.go @@ -49,8 +49,10 @@ type usernameToUserdataMap struct { } // defaultDbIndex systemdb should always be in index 0 -const defaultDbIndex = 0 -const sysDBIndex = math.MaxInt32 +const ( + defaultDbIndex = 0 + sysDBIndex = math.MaxInt32 +) // ImmuServer ... type ImmuServer struct { @@ -89,7 +91,7 @@ type ImmuServer struct { SessManager sessions.Manager } -// DefaultServer ... +// DefaultServer returns a new ImmuServer instance with all configuration options set to their default values. func DefaultServer() *ImmuServer { return &ImmuServer{ OS: immuos.NewStandardOS(),