From 56587ffdaffe2f8cd0781c96c966c28a06be4406 Mon Sep 17 00:00:00 2001 From: Marco Dinis Date: Thu, 18 Jul 2024 22:38:13 +0100 Subject: [PATCH] Re-open the log file by filesystem notify (#43359) * Re-open the log file on OS Signal trigger This PR implements an handler for the CONT signal. The handler will close and re-open the log file. If the log destination is not a file, this is a no-op. Useful for logrotate postrotate hook. * signal replaced with the fsnotify * code review changes: - refactored to launch watcher with process context - make file shared writer as singleton - add test for logrotate case * add locking for write, reopen * - configuration for log section update - test simplification * code review changes: - add closing for file shared writer - make runWatcherFunc not exported * linter fixes * change default file mode for log file simplify setting global watcher * terminate watcher after override global one added test for validating global override * make log file name static for shared writer * replace logic to use finalizer instead * fix possible locking write while reopen is triggered * wrap internal error, fix incorrect unlock * drop configuration flag, make watcher always enabled * tune context passing --------- Co-authored-by: Vadym Popov --- go.mod | 2 +- integrations/event-handler/go.mod | 1 + integrations/event-handler/go.sum | 2 + integrations/terraform/go.mod | 1 + integrations/terraform/go.sum | 2 + lib/config/configuration.go | 35 ++++--- lib/service/servicecfg/config.go | 2 + lib/utils/log/file_writer.go | 164 ++++++++++++++++++++++++++++++ lib/utils/log/file_writer_test.go | 163 +++++++++++++++++++++++++++++ lib/utils/log/writer_finalizer.go | 49 +++++++++ 10 files changed, 407 insertions(+), 14 deletions(-) create mode 100644 lib/utils/log/file_writer.go create mode 100644 lib/utils/log/file_writer_test.go create mode 100644 lib/utils/log/writer_finalizer.go diff --git a/go.mod b/go.mod index bd6a0382349b..0f8e6c0d717d 100644 --- a/go.mod +++ b/go.mod @@ -84,6 +84,7 @@ require ( github.com/elastic/go-elasticsearch/v8 v8.14.0 github.com/elimity-com/scim v0.0.0-20240320110924-172bf2aee9c8 github.com/evanphx/json-patch v5.9.0+incompatible + github.com/fsnotify/fsnotify v1.7.0 github.com/fsouza/fake-gcs-server v1.49.2 github.com/fxamacker/cbor/v2 v2.7.0 github.com/ghodss/yaml v1.0.0 @@ -321,7 +322,6 @@ require ( github.com/fatih/camelcase v1.0.0 // indirect github.com/fatih/color v1.16.0 // indirect github.com/felixge/httpsnoop v1.0.4 // indirect - github.com/fsnotify/fsnotify v1.7.0 // indirect github.com/fvbommel/sortorder v1.1.0 // indirect github.com/gabriel-vasile/mimetype v1.4.3 // indirect github.com/go-asn1-ber/asn1-ber v1.5.5 // indirect diff --git a/integrations/event-handler/go.mod b/integrations/event-handler/go.mod index 139f8a7c2f24..7951ccd86551 100644 --- a/integrations/event-handler/go.mod +++ b/integrations/event-handler/go.mod @@ -128,6 +128,7 @@ require ( github.com/exponent-io/jsonpath v0.0.0-20151013193312-d6023ce2651d // indirect github.com/fatih/color v1.16.0 // indirect github.com/felixge/httpsnoop v1.0.4 // indirect + github.com/fsnotify/fsnotify v1.7.0 // indirect github.com/fxamacker/cbor/v2 v2.7.0 // indirect github.com/ghodss/yaml v1.0.0 // indirect github.com/go-errors/errors v1.4.2 // indirect diff --git a/integrations/event-handler/go.sum b/integrations/event-handler/go.sum index e8fdf59fe3fa..a7b5bef61be2 100644 --- a/integrations/event-handler/go.sum +++ b/integrations/event-handler/go.sum @@ -938,6 +938,8 @@ github.com/foxcpp/go-mockdns v1.0.0 h1:7jBqxd3WDWwi/6WhDvacvH1XsN3rOLXyHM1uhvIx6 github.com/foxcpp/go-mockdns v1.0.0/go.mod h1:lgRN6+KxQBawyIghpnl5CezHFGS9VLzvtVlwxvzXTQ4= github.com/frankban/quicktest v1.14.6 h1:7Xjx+VpznH+oBnejlPUj8oUpdxnVs4f8XU8WnHkI4W8= github.com/frankban/quicktest v1.14.6/go.mod h1:4ptaffx2x8+WTWXmUCuVU6aPUX1/Mz7zb5vbUoiM6w0= +github.com/fsnotify/fsnotify v1.7.0 h1:8JEhPFa5W2WU7YfeZzPNqzMP6Lwt7L2715Ggo0nosvA= +github.com/fsnotify/fsnotify v1.7.0/go.mod h1:40Bi/Hjc2AVfZrqy+aj+yEI+/bRxZnMJyTJwOpGvigM= github.com/fxamacker/cbor/v2 v2.7.0 h1:iM5WgngdRBanHcxugY4JySA0nk1wZorNOpTgCMedv5E= github.com/fxamacker/cbor/v2 v2.7.0/go.mod h1:pxXPTn3joSm21Gbwsv0w9OSA2y1HFR9qXEeXQVeNoDQ= github.com/ghodss/yaml v1.0.0 h1:wQHKEahhL6wmXdzwWG11gIVCkOv05bNOh+Rxn0yngAk= diff --git a/integrations/terraform/go.mod b/integrations/terraform/go.mod index 5e42cd6ff241..13de13322892 100644 --- a/integrations/terraform/go.mod +++ b/integrations/terraform/go.mod @@ -173,6 +173,7 @@ require ( github.com/exponent-io/jsonpath v0.0.0-20151013193312-d6023ce2651d // indirect github.com/fatih/color v1.16.0 // indirect github.com/felixge/httpsnoop v1.0.4 // indirect + github.com/fsnotify/fsnotify v1.7.0 // indirect github.com/fxamacker/cbor/v2 v2.7.0 // indirect github.com/ghodss/yaml v1.0.0 // indirect github.com/go-asn1-ber/asn1-ber v1.5.5 // indirect diff --git a/integrations/terraform/go.sum b/integrations/terraform/go.sum index 84414a55b037..e94474516a53 100644 --- a/integrations/terraform/go.sum +++ b/integrations/terraform/go.sum @@ -1088,6 +1088,8 @@ github.com/foxcpp/go-mockdns v1.0.0 h1:7jBqxd3WDWwi/6WhDvacvH1XsN3rOLXyHM1uhvIx6 github.com/foxcpp/go-mockdns v1.0.0/go.mod h1:lgRN6+KxQBawyIghpnl5CezHFGS9VLzvtVlwxvzXTQ4= github.com/frankban/quicktest v1.14.6 h1:7Xjx+VpznH+oBnejlPUj8oUpdxnVs4f8XU8WnHkI4W8= github.com/frankban/quicktest v1.14.6/go.mod h1:4ptaffx2x8+WTWXmUCuVU6aPUX1/Mz7zb5vbUoiM6w0= +github.com/fsnotify/fsnotify v1.7.0 h1:8JEhPFa5W2WU7YfeZzPNqzMP6Lwt7L2715Ggo0nosvA= +github.com/fsnotify/fsnotify v1.7.0/go.mod h1:40Bi/Hjc2AVfZrqy+aj+yEI+/bRxZnMJyTJwOpGvigM= github.com/fsouza/fake-gcs-server v1.49.2 h1:fukDqzEQM50QkA0jAbl6cLqeDu3maQjwZBuys759TR4= github.com/fsouza/fake-gcs-server v1.49.2/go.mod h1:17SYzJEXRcaAA5ATwwvgBkSIqIy7r1icnGM0y/y4foY= github.com/fxamacker/cbor/v2 v2.7.0 h1:iM5WgngdRBanHcxugY4JySA0nk1wZorNOpTgCMedv5E= diff --git a/lib/config/configuration.go b/lib/config/configuration.go index 82646f1c000a..8a26e74b6933 100644 --- a/lib/config/configuration.go +++ b/lib/config/configuration.go @@ -23,9 +23,11 @@ package config import ( + "context" "crypto/x509" "errors" "io" + "io/fs" "log/slog" "maps" "net" @@ -70,6 +72,13 @@ import ( logutils "github.com/gravitational/teleport/lib/utils/log" ) +const ( + // logFileDefaultMode is the preferred permissions mode for log file. + logFileDefaultMode fs.FileMode = 0o644 + // logFileDefaultFlag is the preferred flags set to log file. + logFileDefaultFlag = os.O_WRONLY | os.O_CREATE | os.O_APPEND +) + // CommandLineFlags stores command line flag values, it's a much simplified subset // of Teleport configuration (which is fully expressed via YAML config file) type CommandLineFlags struct { @@ -757,12 +766,12 @@ func applyLogConfig(loggerConfig Log, cfg *servicecfg.Config) error { var w io.Writer switch loggerConfig.Output { case "": - w = os.Stderr + w = logutils.NewSharedWriter(os.Stderr) case "stderr", "error", "2": - w = os.Stderr + w = logutils.NewSharedWriter(os.Stderr) cfg.Console = io.Discard // disable console printing case "stdout", "out", "1": - w = os.Stdout + w = logutils.NewSharedWriter(os.Stdout) cfg.Console = io.Discard // disable console printing case teleport.Syslog: w = os.Stderr @@ -780,14 +789,20 @@ func applyLogConfig(loggerConfig Log, cfg *servicecfg.Config) error { logger.ReplaceHooks(make(log.LevelHooks)) logger.AddHook(hook) + // If syslog output has been configured and is supported by the operating system, + // then the shared writer is not needed because the syslog writer is already + // protected with a mutex. w = sw default: - // assume it's a file path: - logFile, err := os.Create(loggerConfig.Output) + // Assume this is a file path. + sharedWriter, err := logutils.NewFileSharedWriter(loggerConfig.Output, logFileDefaultFlag, logFileDefaultMode) if err != nil { - return trace.Wrap(err, "failed to create the log file") + return trace.Wrap(err, "failed to init the log file shared writer") + } + w = logutils.NewWriterFinalizer[*logutils.FileSharedWriter](sharedWriter) + if err := sharedWriter.RunWatcherReopen(context.Background()); err != nil { + return trace.Wrap(err) } - w = logFile } level := new(slog.LevelVar) @@ -816,12 +831,6 @@ func applyLogConfig(loggerConfig Log, cfg *servicecfg.Config) error { return trace.Wrap(err) } - // If syslog output has been configured and is supported by the operating system, - // then the shared writer is not needed because the syslog writer is already - // protected with a mutex. - if len(logger.Hooks) == 0 { - w = logutils.NewSharedWriter(w) - } var slogLogger *slog.Logger switch strings.ToLower(loggerConfig.Format.Output) { case "": diff --git a/lib/service/servicecfg/config.go b/lib/service/servicecfg/config.go index 456321cdf35e..6d14bce4e5b2 100644 --- a/lib/service/servicecfg/config.go +++ b/lib/service/servicecfg/config.go @@ -222,9 +222,11 @@ type Config struct { // Log optionally specifies the logger. // Deprecated: use Logger instead. Log utils.Logger + // Logger outputs messages using slog. The underlying handler respects // the user supplied logging config. Logger *slog.Logger + // LoggerLevel defines the Logger log level. LoggerLevel *slog.LevelVar diff --git a/lib/utils/log/file_writer.go b/lib/utils/log/file_writer.go new file mode 100644 index 000000000000..207ada327052 --- /dev/null +++ b/lib/utils/log/file_writer.go @@ -0,0 +1,164 @@ +/* + * Teleport + * Copyright (C) 2024 Gravitational, Inc. + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU Affero General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU Affero General Public License for more details. + * + * You should have received a copy of the GNU Affero General Public License + * along with this program. If not, see . + */ + +package log + +import ( + "context" + "errors" + "io/fs" + "log/slog" + "os" + "path/filepath" + "sync" + + "github.com/fsnotify/fsnotify" + "github.com/gravitational/trace" +) + +var ( + // ErrFileSharedWriterClosed is returned when file shared writer is already closed. + ErrFileSharedWriterClosed = errors.New("file shared writer is closed") +) + +// FileSharedWriter is similar to SharedWriter except that it requires a `os.File` instead of a `io.Writer`. +// This is to allow the File reopen required by logrotate and similar tools. +type FileSharedWriter struct { + logFileName string + fileFlag int + fileMode fs.FileMode + file *os.File + watcher *fsnotify.Watcher + closed bool + + lock sync.Mutex +} + +// NewFileSharedWriter wraps the provided [os.File] in a writer that is thread safe, +// with ability to enable filesystem notification watch and reopen file on specific events. +func NewFileSharedWriter(logFileName string, flag int, mode fs.FileMode) (*FileSharedWriter, error) { + if logFileName == "" { + return nil, trace.BadParameter("log file name is not set") + } + logFile, err := os.OpenFile(logFileName, flag, mode) + if err != nil { + return nil, trace.ConvertSystemError(err) + } + watcher, err := fsnotify.NewWatcher() + if err != nil { + return nil, trace.Wrap(err) + } + + return &FileSharedWriter{ + logFileName: logFileName, + fileFlag: flag, + fileMode: mode, + file: logFile, + watcher: watcher, + }, nil +} + +// Write writes len(b) bytes from b to the File. +func (s *FileSharedWriter) Write(b []byte) (int, error) { + s.lock.Lock() + defer s.lock.Unlock() + if s.closed { + return 0, ErrFileSharedWriterClosed + } + + return s.file.Write(b) +} + +// Reopen closes the file and opens it again using APPEND mode. +func (s *FileSharedWriter) Reopen() error { + // If opening the file is locked we should not acquire a lock and block write. + file, err := os.OpenFile(s.logFileName, s.fileFlag, s.fileMode) + if err != nil { + return trace.Wrap(err) + } + + s.lock.Lock() + if s.closed { + s.lock.Unlock() + _ = file.Close() + return trace.Wrap(ErrFileSharedWriterClosed) + } + oldLogFile := s.file + s.file = file + s.lock.Unlock() + + return trace.Wrap(oldLogFile.Close()) +} + +// RunWatcherReopen runs a filesystem watcher for rename/remove events to reopen the log. +func (s *FileSharedWriter) RunWatcherReopen(ctx context.Context) error { + s.lock.Lock() + defer s.lock.Unlock() + if s.closed { + return trace.Wrap(ErrFileSharedWriterClosed) + } + + return s.runWatcherFunc(ctx, s.Reopen) +} + +// runWatcherFunc spawns goroutine with the watcher loop to consume events of renaming +// or removing the log file to trigger the action function when event appeared. +func (s *FileSharedWriter) runWatcherFunc(ctx context.Context, action func() error) error { + go func() { + for { + select { + case event, ok := <-s.watcher.Events: + if !ok { + return + } + if s.logFileName == event.Name && (event.Has(fsnotify.Rename) || event.Has(fsnotify.Remove)) { + slog.DebugContext(ctx, "Log file was moved/removed", "file", event.Name) + if err := action(); err != nil { + slog.ErrorContext(ctx, "Failed to reopen file", "error", err, "file", event.Name) + continue + } + } + case err, ok := <-s.watcher.Errors: + if !ok { + return + } + slog.ErrorContext(ctx, "Error received on logger watcher", "error", err) + } + } + }() + + logDirParent := filepath.Dir(s.logFileName) + if err := s.watcher.Add(logDirParent); err != nil { + return trace.Wrap(err) + } + + return nil +} + +// Close stops the internal watcher and close the log file. +func (s *FileSharedWriter) Close() error { + s.lock.Lock() + defer s.lock.Unlock() + + if s.closed { + return trace.Wrap(ErrFileSharedWriterClosed) + } + s.closed = true + + return trace.NewAggregate(s.watcher.Close(), s.file.Close()) +} diff --git a/lib/utils/log/file_writer_test.go b/lib/utils/log/file_writer_test.go new file mode 100644 index 000000000000..053b52a6d09c --- /dev/null +++ b/lib/utils/log/file_writer_test.go @@ -0,0 +1,163 @@ +/* + * Teleport + * Copyright (C) 2024 Gravitational, Inc. + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU Affero General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU Affero General Public License for more details. + * + * You should have received a copy of the GNU Affero General Public License + * along with this program. If not, see . + */ + +package log + +import ( + "context" + "fmt" + "io" + "os" + "path/filepath" + "runtime" + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +// TestFileSharedWriterNotify checks that if we create the file with shared writer and enable +// watcher functionality, we should expect the file to be reopened after renaming the original one. +func TestFileSharedWriterNotify(t *testing.T) { + logDir := t.TempDir() + testFileMode := os.FileMode(0o600) + testFileFlag := os.O_WRONLY | os.O_CREATE | os.O_APPEND + logFileName := filepath.Join(logDir, "test.log") + + logWriter, err := NewFileSharedWriter(logFileName, testFileFlag, testFileMode) + require.NoError(t, err, "failed to init the file shared writer") + + t.Cleanup(func() { + require.NoError(t, logWriter.Close()) + }) + + signal := make(chan struct{}) + err = logWriter.runWatcherFunc(context.Background(), func() error { + err := logWriter.Reopen() + signal <- struct{}{} + return err + }) + require.NoError(t, err, "failed to run reopen watcher") + + // Write a custom phrase to ensure that the original file was written to before the rotation. + firstPhrase := "first-write" + n, err := logWriter.Write([]byte(firstPhrase)) + require.NoError(t, err) + require.Equal(t, len(firstPhrase), n, "failed to write first phrase") + + data, err := os.ReadFile(logFileName) + require.NoError(t, err, "cannot read log file") + require.Equal(t, firstPhrase, string(data), "first written phrase does not match") + + // Move the original file to a new location to simulate the logrotate operation. + err = os.Rename(logFileName, fmt.Sprintf("%s.1", logFileName)) + require.NoError(t, err, "can't rename log file") + + select { + case <-time.After(5 * time.Second): + require.Fail(t, "timed out waiting for file reopen") + case <-signal: + } + + // Write a second custom phrase to ensure the previous one is not in the file. + secondPhrase := "second-write" + n, err = logWriter.Write([]byte(secondPhrase)) + require.NoError(t, err) + require.Equal(t, len(secondPhrase), n, "failed to write second phrase") + + data, err = os.ReadFile(logFileName) + require.NoError(t, err, "cannot read log file") + require.Equal(t, secondPhrase, string(data), "second written phrase does not match") +} + +// TestFileSharedWriterFinalizer verifies the logic with closing file shared writer +// after overriding it in `logger.SetOutput`. +func TestFileSharedWriterFinalizer(t *testing.T) { + // output simulates setting the file shared writer to logger. + var output io.WriteCloser + + logDir := t.TempDir() + testFileMode := os.FileMode(0o600) + testFileFlag := os.O_WRONLY | os.O_CREATE | os.O_APPEND + logFileName := filepath.Join(logDir, "test.log") + + // Initiate the first file shared writer and set it to output. + var firstWatcherTriggered bool + firstLogWriter, err := NewFileSharedWriter(logFileName, testFileFlag, testFileMode) + require.NoError(t, err, "failed to init the file shared writer") + + err = firstLogWriter.runWatcherFunc(context.Background(), func() error { + firstWatcherTriggered = true + return nil + }) + require.NoError(t, err, "failed to run reopen watcher") + + // Set wrapped file shared writer to fake logger output variable. + output = NewWriterFinalizer(firstLogWriter) + _, err = output.Write([]byte("test")) + require.NoError(t, err) + + // Initiate the second file shared writer and override it in common output, + // previous must be closed automatically by finalizer and stop reacting on events. + secondLogWriter, err := NewFileSharedWriter(logFileName, testFileFlag, testFileMode) + require.NoError(t, err, "failed to init the file shared writer") + + signal := make(chan struct{}) + err = secondLogWriter.runWatcherFunc(context.Background(), func() error { + err := secondLogWriter.Reopen() + signal <- struct{}{} + return err + }) + require.NoError(t, err, "failed to run reopen watcher") + + // Overriding second file shared writer to free resources of the first one + // and trigger finalizing logic. + output = secondLogWriter + runtime.GC() + + // Move the original file to a new location to simulate the logrotate operation. + err = os.Rename(logFileName, fmt.Sprintf("%s.1", logFileName)) + require.NoError(t, err, "can't rename log file") + + select { + case <-time.After(5 * time.Second): + require.Fail(t, "timed out waiting for file reopen") + case <-signal: + } + + // Check that if we set new global file shared writer we close first one. + require.False(t, firstWatcherTriggered) + + // Check that we receive the error if we are going to try to run watcher + // again for closed one. + err = firstLogWriter.RunWatcherReopen(context.Background()) + require.ErrorIs(t, err, ErrFileSharedWriterClosed) + + // First file shared writer must be already closed and produce error after + // trying to close it second time. + err = firstLogWriter.Close() + require.ErrorIs(t, err, ErrFileSharedWriterClosed) + + // Write must not fail after override. + _, err = output.Write([]byte("test")) + require.NoError(t, err) + + t.Cleanup(func() { + require.NoError(t, output.Close()) + }) +} diff --git a/lib/utils/log/writer_finalizer.go b/lib/utils/log/writer_finalizer.go new file mode 100644 index 000000000000..b90de0e8e3fd --- /dev/null +++ b/lib/utils/log/writer_finalizer.go @@ -0,0 +1,49 @@ +/* + * Teleport + * Copyright (C) 2024 Gravitational, Inc. + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU Affero General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU Affero General Public License for more details. + * + * You should have received a copy of the GNU Affero General Public License + * along with this program. If not, see . + */ + +package log + +import ( + "io" + "runtime" +) + +// WriterFinalizer is a wrapper for the [io.WriteCloser] to automate resource cleanup. +type WriterFinalizer[T io.WriteCloser] struct { + writer T +} + +// NewWriterFinalizer wraps the provided writer [io.WriteCloser] to trigger Close function +// after writer is unassigned from any variable. +func NewWriterFinalizer[T io.WriteCloser](writer T) *WriterFinalizer[T] { + wr := &WriterFinalizer[T]{ + writer: writer, + } + runtime.SetFinalizer(wr, (*WriterFinalizer[T]).Close) + return wr +} + +// Write writes len(b) bytes from b to the writer. +func (w *WriterFinalizer[T]) Write(b []byte) (int, error) { + return w.writer.Write(b) +} + +// Close wraps closing function of internal writer. +func (w *WriterFinalizer[T]) Close() error { + return w.writer.Close() +}