Merge pull request #592 from rod-hynes/master

Mitigate "permission denied" errors when writing logs

Server/main.go

@@ -301,7 +301,10 @@ func panicHandler(output string) {
 		// Logs are written to the configured file name. If no name is specified, logs are written to stderr
 		var jsonWriter io.Writer
 		if config.LogFilename != "" {
-			panicLog, err := rotate.NewRotatableFileWriter(config.LogFilename, 0666)
+
+			retries, create, mode := config.GetLogFileReopenConfig()
+			panicLog, err := rotate.NewRotatableFileWriter(
+				config.LogFilename, retries, create, mode)
 			if err != nil {
 				fmt.Printf("unable to set panic log output: %s\n%s\n", err, output)
 				os.Exit(1)

psiphon/server/config.go

@@ -29,6 +29,7 @@ import (
 	"encoding/pem"
 	"fmt"
 	"net"
+	"os"
 	"strconv"
 	"strings"
 	"sync/atomic"
@@ -60,6 +61,7 @@ const (
 	SSH_OBFUSCATED_KEY_BYTE_LENGTH                      = 32
 	PERIODIC_GARBAGE_COLLECTION                         = 120 * time.Second
 	STOP_ESTABLISH_TUNNELS_ESTABLISHED_CLIENT_THRESHOLD = 20
+	DEFAULT_LOG_FILE_REOPEN_RETRIES                     = 10
 )
 
 // Config specifies the configuration and behavior of a Psiphon
@@ -74,6 +76,22 @@ type Config struct {
 	// to. When blank, logs are written to stderr.
 	LogFilename string
 
+	// LogFileReopenRetries specifies how many retries, each with a 1ms delay,
+	// will be attempted after reopening a rotated log file fails. Retries
+	// mitigate any race conditions between writes/reopens and file operations
+	// performed by external log managers, such as logrotate.
+	//
+	// When omitted, DEFAULT_LOG_FILE_REOPEN_RETRIES is used.
+	LogFileReopenRetries *int
+
+	// LogFileCreateMode specifies that the Psiphon server should create a new
+	// log file when one is not found, such as after rotation with logrotate
+	// configured with nocreate. The value is the os.FileMode value to use when
+	// creating the file.
+	//
+	// When omitted, the Psiphon server does not create log files.
+	LogFileCreateMode *int
+
 	// SkipPanickingLogWriter disables panicking when
 	// unable to write any logs.
 	SkipPanickingLogWriter bool
@@ -404,6 +422,34 @@ type Config struct {
 	dumpProfilesOnStopEstablishTunnelsDone         int32
 }
 
+// GetLogFileReopenConfig gets the reopen retries, and create/mode inputs for
+// rotate.NewRotatableFileWriter, which is used when writing to log files.
+//
+// By default, we expect the log files to be managed by logrotate, with
+// logrotate configured to re-create the next log file after rotation. As
+// described in the documentation for rotate.NewRotatableFileWriter, and as
+// observed in production, we occasionally need retries when attempting to
+// reopen the log file post-rotation; and we avoid conflicts, and spurious
+// re-rotations, by disabling file create in rotate.NewRotatableFileWriter. In
+// large scale production, incidents requiring retry are very rare, so the
+// retry delay is not expected to have a significant impact on performance.
+//
+// The defaults may be overriden in the Config.
+func (config *Config) GetLogFileReopenConfig() (int, bool, os.FileMode) {
+
+	retries := DEFAULT_LOG_FILE_REOPEN_RETRIES
+	if config.LogFileReopenRetries != nil {
+		retries = *config.LogFileReopenRetries
+	}
+	create := false
+	mode := os.FileMode(0)
+	if config.LogFileCreateMode != nil {
+		create = true
+		mode = os.FileMode(*config.LogFileCreateMode)
+	}
+	return retries, create, mode
+}
+
 // RunWebServer indicates whether to run a web server component.
 func (config *Config) RunWebServer() bool {
 	return config.WebServerPort > 0
@@ -778,9 +824,14 @@ func GenerateConfig(params *GenerateConfigParams) ([]byte, []byte, []byte, []byt
 		logLevel = "info"
 	}
 
+	// For testing, set the Psiphon server to create its log files; we do not
+	// expect tests to necessarily run under log managers, such as logrotate.
+	createMode := 0666
+
 	config := &Config{
 		LogLevel:                       logLevel,
 		LogFilename:                    params.LogFilename,
+		LogFileCreateMode:              &createMode,
 		SkipPanickingLogWriter:         params.SkipPanickingLogWriter,
 		GeoIPDatabaseFilenames:         nil,
 		HostID:                         "example-host-id",

psiphon/server/log.go

@@ -263,7 +263,10 @@ func InitLogging(config *Config) (retErr error) {
 		var logWriter io.Writer
 
 		if config.LogFilename != "" {
-			logWriter, err = rotate.NewRotatableFileWriter(config.LogFilename, 0666)
+
+			retries, create, mode := config.GetLogFileReopenConfig()
+			logWriter, err = rotate.NewRotatableFileWriter(
+				config.LogFilename, retries, create, mode)
 			if err != nil {
 				retErr = errors.Trace(err)
 				return

vendor/github.com/Psiphon-Inc/rotate-safe-writer/rotate.go

@@ -28,6 +28,7 @@ package rotate
 import (
 	"os"
 	"sync"
+	"time"
 )
 
 // RotatableFileWriter implementation that knows when the file has been rotated and re-opens it
@@ -35,8 +36,10 @@ type RotatableFileWriter struct {
 	sync.Mutex
 	file     *os.File
 	fileInfo *os.FileInfo
-	mode     os.FileMode
 	name     string
+	retries  int
+	create   bool
+	mode     os.FileMode
 }
 
 // Close closes the underlying file
@@ -56,7 +59,12 @@ func (f *RotatableFileWriter) reopen() error {
 		f.fileInfo = nil
 	}
 
-	reopened, err := os.OpenFile(f.name, os.O_WRONLY|os.O_APPEND|os.O_CREATE, f.mode)
+	flags := os.O_WRONLY | os.O_APPEND
+	if f.create {
+		flags |= os.O_CREATE
+	}
+
+	reopened, err := os.OpenFile(f.name, flags, f.mode)
 	if err != nil {
 		return err
 	}
@@ -73,10 +81,22 @@ func (f *RotatableFileWriter) reopen() error {
 	return nil
 }
 
+func (f *RotatableFileWriter) reopenWithRetries() error {
+	var err error
+	for i := 0; i <= f.retries; i++ {
+		err = f.reopen()
+		if err == nil {
+			break
+		}
+		time.Sleep(1 * time.Millisecond)
+	}
+	return err
+}
+
 // Reopen provides the concurrency safe implementation of re-opening the file, and updating the struct's fileInfo
 func (f *RotatableFileWriter) Reopen() error {
 	f.Lock()
-	err := f.reopen()
+	err := f.reopenWithRetries()
 	f.Unlock()
 
 	return err
@@ -92,7 +112,7 @@ func (f *RotatableFileWriter) Write(p []byte) (int, error) {
 	// could be left nil, causing subsequent writes to panic. This will attempt
 	// to re-open the file handle prior to writing in that case
 	if f.file == nil || f.fileInfo == nil {
-		err := f.reopen()
+		err := f.reopenWithRetries()
 		if err != nil {
 			return 0, err
 		}
@@ -100,7 +120,7 @@ func (f *RotatableFileWriter) Write(p []byte) (int, error) {
 
 	currentFileInfo, err := os.Stat(f.name)
 	if err != nil || !os.SameFile(*f.fileInfo, currentFileInfo) {
-		err := f.reopen()
+		err := f.reopenWithRetries()
 		if err != nil {
 			return 0, err
 		}
@@ -110,7 +130,7 @@ func (f *RotatableFileWriter) Write(p []byte) (int, error) {
 
 	// If the write fails with nothing written, attempt to re-open the file and retry the write
 	if bytesWritten == 0 && err != nil {
-		err = f.reopen()
+		err = f.reopenWithRetries()
 		if err != nil {
 			return 0, err
 		}
@@ -121,16 +141,39 @@ func (f *RotatableFileWriter) Write(p []byte) (int, error) {
 	return bytesWritten, err
 }
 
-// NewRotatableFileWriter opens a file for appending and writing that can be safely rotated
-func NewRotatableFileWriter(name string, mode os.FileMode) (*RotatableFileWriter, error) {
+// NewRotatableFileWriter opens a file for appending and writing that can be
+// safely rotated.
+//
+// If retries is greater than 0, RotatableFileWriter will make that number of
+// additional attempts to reopen a rotated file after a file open failure,
+// following a 1ms delay. This option can mitigate race conditions that may
+// occur when RotatableFileWriter reopens the file while an underlying file
+// manager, such as logrotate, is recreating the file and setting its
+// properties.
+//
+// When create is true, RotatableFileWriter will attempt to create the file
+// (using mode), if it does not exist, when reopening the file. Set create to
+// false to avoid conflicts with an underlying file manager, such as
+// logrotate. logrotate, unless configured with nocreate, creates files with
+// O_EXCL and re-rotates/retries if another process has created the file.
+func NewRotatableFileWriter(
+	name string,
+	retries int,
+	create bool,
+	mode os.FileMode) (*RotatableFileWriter, error) {
+
+	if retries < 0 {
+		retries = 0
+	}
+
 	rotatableFileWriter := RotatableFileWriter{
-		file:     nil,
-		name:     name,
-		mode:     mode,
-		fileInfo: nil,
+		name:    name,
+		retries: retries,
+		create:  create,
+		mode:    mode,
 	}
 
-	err := rotatableFileWriter.reopen()
+	err := rotatableFileWriter.reopenWithRetries()
 	if err != nil {
 		return nil, err
 	}

vendor/vendor.json

@@ -15,10 +15,10 @@
 			"revisionTime": "2017-07-02T08:40:17Z"
 		},
 		{
-			"checksumSHA1": "aFs1ojFW1UmUNMtN6rdRJ2FEIRE=",
+			"checksumSHA1": "sfwh75+6RErl2wUTOYb5PSVm7ik=",
 			"path": "github.com/Psiphon-Inc/rotate-safe-writer",
-			"revision": "b276127301a99aa7102ebdc6f509fc8d890900d0",
-			"revisionTime": "2017-02-28T16:03:01Z"
+			"revision": "464a7a37606efa061cb3021e7bb9fa3642e1e74d",
+			"revisionTime": "2021-03-03T14:09:23Z"
 		},
 		{
 			"checksumSHA1": "okYVKU03vmD+0tpqfhvXEubcaCw=",