From 5a9b744dd13236c543b8e089e0561116bea80020 Mon Sep 17 00:00:00 2001 From: Ben McClelland Date: Tue, 25 Jul 2023 22:53:48 -0700 Subject: [PATCH] fix: allow logging to user specified log files This also cleans up some the of the error output to send to stderr. This adds the Shutdown() to the logging interface, so we can keep the log file open and just append entries. This add HangUp() to the logging interface for log rotations. --- cmd/versitygw/main.go | 44 ++++++-- cmd/versitygw/signal.go | 2 + s3log/audit-logger.go | 10 +- s3log/file.go | 240 ++++++++++++++++++++++------------------ s3log/webhook.go | 83 ++++++++------ 5 files changed, 223 insertions(+), 156 deletions(-) diff --git a/cmd/versitygw/main.go b/cmd/versitygw/main.go index 907a531f..b6e62b77 100644 --- a/cmd/versitygw/main.go +++ b/cmd/versitygw/main.go @@ -40,7 +40,7 @@ var ( kafkaURL, kafkaTopic, kafkaKey string natsURL, natsTopic string logWebhookURL string - accessLog bool + accessLog string debug bool ) @@ -147,14 +147,16 @@ func initFlags() []cli.Flag { Usage: "enable debug output", Destination: &debug, }, - &cli.BoolFlag{ + &cli.StringFlag{ Name: "access-log", - Usage: "enable server access logging in the root directory", + Usage: "enable server access logging to specified file", + EnvVars: []string{"LOGFILE"}, Destination: &accessLog, }, &cli.StringFlag{ Name: "log-webhook-url", Usage: "webhook url to send the audit logs", + EnvVars: []string{"WEBHOOK"}, Destination: &logWebhookURL, }, &cli.StringFlag{ @@ -229,7 +231,7 @@ func runGateway(ctx *cli.Context, be backend.Backend, s auth.Storer) error { } logger, err := s3log.InitLogger(&s3log.LogConfig{ - IsFile: accessLog, + LogFile: accessLog, WebhookURL: logWebhookURL, }) if err != nil { @@ -258,12 +260,32 @@ func runGateway(ctx *cli.Context, be backend.Backend, s auth.Storer) error { c := make(chan error, 1) go func() { c <- srv.Serve() }() - select { - case <-ctx.Done(): - be.Shutdown() - return ctx.Err() - case err := <-c: - be.Shutdown() - return err + // for/select blocks until shutdown +Loop: + for { + select { + case <-ctx.Done(): + err = ctx.Err() + break Loop + case err = <-c: + break Loop + case <-sigHup: + if logger != nil { + err = logger.HangUp() + if err != nil { + err = fmt.Errorf("HUP logger: %w", err) + break Loop + } + } + } } + + be.Shutdown() + if logger != nil { + lerr := logger.Shutdown() + if lerr != nil { + fmt.Fprintf(os.Stderr, "shutdown logger: %v\n", lerr) + } + } + return err } diff --git a/cmd/versitygw/signal.go b/cmd/versitygw/signal.go index 147e55e9..a92dbd54 100644 --- a/cmd/versitygw/signal.go +++ b/cmd/versitygw/signal.go @@ -23,6 +23,7 @@ import ( var ( sigDone = make(chan bool, 1) + sigHup = make(chan bool, 1) ) func setupSignalHandler() { @@ -36,6 +37,7 @@ func setupSignalHandler() { case syscall.SIGINT, syscall.SIGTERM: sigDone <- true case syscall.SIGHUP: + sigHup <- true } } }() diff --git a/s3log/audit-logger.go b/s3log/audit-logger.go index fc49d3b5..5f302663 100644 --- a/s3log/audit-logger.go +++ b/s3log/audit-logger.go @@ -27,6 +27,8 @@ import ( type AuditLogger interface { Log(ctx *fiber.Ctx, err error, body []byte, meta LogMeta) + HangUp() error + Shutdown() error } type LogMeta struct { @@ -36,7 +38,7 @@ type LogMeta struct { } type LogConfig struct { - IsFile bool + LogFile string WebhookURL string } @@ -70,14 +72,14 @@ type LogFields struct { } func InitLogger(cfg *LogConfig) (AuditLogger, error) { - if cfg.WebhookURL != "" && cfg.IsFile { + if cfg.WebhookURL != "" && cfg.LogFile != "" { return nil, fmt.Errorf("there should be specified one of the following: file, webhook") } if cfg.WebhookURL != "" { return InitWebhookLogger(cfg.WebhookURL) } - if cfg.IsFile { - return InitFileLogger() + if cfg.LogFile != "" { + return InitFileLogger(cfg.LogFile) } return nil, nil diff --git a/s3log/file.go b/s3log/file.go index d6cd09e8..e96f2910 100644 --- a/s3log/file.go +++ b/s3log/file.go @@ -16,9 +16,7 @@ package s3log import ( "crypto/tls" - "errors" "fmt" - "io/fs" "os" "strings" "sync" @@ -29,36 +27,43 @@ import ( ) const ( - logFile = "access.log" logFileMode = 0600 timeFormat = "02/January/2006:15:04:05 -0700" ) +// FileLogger is a local file audit log type FileLogger struct { - LogFields - mu sync.Mutex + logfile string + f *os.File + gotErr bool + mu sync.Mutex } var _ AuditLogger = &FileLogger{} -func InitFileLogger() (AuditLogger, error) { - _, err := os.ReadFile(logFile) - if err != nil && errors.Is(err, fs.ErrNotExist) { - err := os.WriteFile(logFile, []byte{}, logFileMode) - if err != nil { - return nil, err - } else { - return nil, err - } +// InitFileLogger initializes audit logs to local file +func InitFileLogger(logname string) (AuditLogger, error) { + f, err := os.OpenFile(logname, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) + if err != nil { + return nil, fmt.Errorf("open log: %w", err) } - return &FileLogger{}, nil + f.WriteString(fmt.Sprintf("log starts %v\n", time.Now())) + + return &FileLogger{logfile: logname, f: f}, nil } +// Log sends log message to file logger func (f *FileLogger) Log(ctx *fiber.Ctx, err error, body []byte, meta LogMeta) { f.mu.Lock() defer f.mu.Unlock() + if f.gotErr { + return + } + + lf := LogFields{} + access := "-" reqURI := ctx.Request().URI().String() path := strings.Split(ctx.Path(), "/") @@ -68,8 +73,8 @@ func (f *FileLogger) Log(ctx *fiber.Ctx, err error, body []byte, meta LogMeta) { startTime := ctx.Locals("startTime").(time.Time) tlsConnState := ctx.Context().TLSConnectionState() if tlsConnState != nil { - f.CipherSuite = tls.CipherSuiteName(tlsConnState.CipherSuite) - f.TLSVersion = getTLSVersionName(tlsConnState.Version) + lf.CipherSuite = tls.CipherSuiteName(tlsConnState.CipherSuite) + lf.TLSVersion = getTLSVersionName(tlsConnState.Version) } if err != nil { @@ -88,117 +93,138 @@ func (f *FileLogger) Log(ctx *fiber.Ctx, err error, body []byte, meta LogMeta) { access = ctx.Locals("access").(string) } - f.BucketOwner = meta.BucketOwner - f.Bucket = bucket - f.Time = time.Now() - f.RemoteIP = ctx.IP() - f.Requester = access - f.RequestID = genID() - f.Operation = meta.Action - f.Key = object - f.RequestURI = reqURI - f.HttpStatus = httpStatus - f.ErrorCode = errorCode - f.BytesSent = len(body) - f.ObjectSize = meta.ObjectSize - f.TotalTime = time.Since(startTime).Milliseconds() - f.TurnAroundTime = time.Since(startTime).Milliseconds() - f.Referer = ctx.Get("Referer") - f.UserAgent = ctx.Get("User-Agent") - f.VersionID = ctx.Query("versionId") - f.HostID = ctx.Get("X-Amz-Id-2") - f.SignatureVersion = "SigV4" - f.AuthenticationType = "AuthHeader" - f.HostHeader = fmt.Sprintf("s3.%v.amazonaws.com", ctx.Locals("region").(string)) - f.AccessPointARN = fmt.Sprintf("arn:aws:s3:::%v", strings.Join(path, "/")) - f.AclRequired = "Yes" + lf.BucketOwner = meta.BucketOwner + lf.Bucket = bucket + lf.Time = time.Now() + lf.RemoteIP = ctx.IP() + lf.Requester = access + lf.RequestID = genID() + lf.Operation = meta.Action + lf.Key = object + lf.RequestURI = reqURI + lf.HttpStatus = httpStatus + lf.ErrorCode = errorCode + lf.BytesSent = len(body) + lf.ObjectSize = meta.ObjectSize + lf.TotalTime = time.Since(startTime).Milliseconds() + lf.TurnAroundTime = time.Since(startTime).Milliseconds() + lf.Referer = ctx.Get("Referer") + lf.UserAgent = ctx.Get("User-Agent") + lf.VersionID = ctx.Query("versionId") + lf.HostID = ctx.Get("X-Amz-Id-2") + lf.SignatureVersion = "SigV4" + lf.AuthenticationType = "AuthHeader" + lf.HostHeader = fmt.Sprintf("s3.%v.amazonaws.com", ctx.Locals("region").(string)) + lf.AccessPointARN = fmt.Sprintf("arn:aws:s3:::%v", strings.Join(path, "/")) + lf.AclRequired = "Yes" - f.writeLog() + f.writeLog(lf) } -func (fl *FileLogger) writeLog() { - if fl.BucketOwner == "" { - fl.BucketOwner = "-" +func (f *FileLogger) writeLog(lf LogFields) { + if lf.BucketOwner == "" { + lf.BucketOwner = "-" } - if fl.Bucket == "" { - fl.Bucket = "-" + if lf.Bucket == "" { + lf.Bucket = "-" } - if fl.RemoteIP == "" { - fl.RemoteIP = "-" + if lf.RemoteIP == "" { + lf.RemoteIP = "-" } - if fl.Requester == "" { - fl.Requester = "-" + if lf.Requester == "" { + lf.Requester = "-" } - if fl.Operation == "" { - fl.Operation = "-" + if lf.Operation == "" { + lf.Operation = "-" } - if fl.Key == "" { - fl.Key = "-" + if lf.Key == "" { + lf.Key = "-" } - if fl.RequestURI == "" { - fl.RequestURI = "-" + if lf.RequestURI == "" { + lf.RequestURI = "-" } - if fl.ErrorCode == "" { - fl.ErrorCode = "-" + if lf.ErrorCode == "" { + lf.ErrorCode = "-" } - if fl.Referer == "" { - fl.Referer = "-" + if lf.Referer == "" { + lf.Referer = "-" } - if fl.UserAgent == "" { - fl.UserAgent = "-" + if lf.UserAgent == "" { + lf.UserAgent = "-" } - if fl.VersionID == "" { - fl.VersionID = "-" + if lf.VersionID == "" { + lf.VersionID = "-" } - if fl.HostID == "" { - fl.HostID = "-" + if lf.HostID == "" { + lf.HostID = "-" } - if fl.CipherSuite == "" { - fl.CipherSuite = "-" + if lf.CipherSuite == "" { + lf.CipherSuite = "-" } - if fl.HostHeader == "" { - fl.HostHeader = "-" + if lf.HostHeader == "" { + lf.HostHeader = "-" } - if fl.TLSVersion == "" { - fl.TLSVersion = "-" + if lf.TLSVersion == "" { + lf.TLSVersion = "-" } - log := fmt.Sprintf("\n%v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v", - fl.BucketOwner, - fl.Bucket, - fmt.Sprintf("[%v]", fl.Time.Format(timeFormat)), - fl.RemoteIP, - fl.Requester, - fl.RequestID, - fl.Operation, - fl.Key, - fl.RequestURI, - fl.HttpStatus, - fl.ErrorCode, - fl.BytesSent, - fl.ObjectSize, - fl.TotalTime, - fl.TurnAroundTime, - fl.Referer, - fl.UserAgent, - fl.VersionID, - fl.HostID, - fl.SignatureVersion, - fl.CipherSuite, - fl.AuthenticationType, - fl.HostHeader, - fl.TLSVersion, - fl.AccessPointARN, - fl.AclRequired, + log := fmt.Sprintf("%v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v %v\n", + lf.BucketOwner, + lf.Bucket, + fmt.Sprintf("[%v]", lf.Time.Format(timeFormat)), + lf.RemoteIP, + lf.Requester, + lf.RequestID, + lf.Operation, + lf.Key, + lf.RequestURI, + lf.HttpStatus, + lf.ErrorCode, + lf.BytesSent, + lf.ObjectSize, + lf.TotalTime, + lf.TurnAroundTime, + lf.Referer, + lf.UserAgent, + lf.VersionID, + lf.HostID, + lf.SignatureVersion, + lf.CipherSuite, + lf.AuthenticationType, + lf.HostHeader, + lf.TLSVersion, + lf.AccessPointARN, + lf.AclRequired, ) - file, err := os.OpenFile(logFile, os.O_APPEND|os.O_CREATE|os.O_WRONLY, logFileMode) + _, err := f.f.WriteString(log) if err != nil { - fmt.Printf("error opening the log file: %v", err.Error()) - } - defer file.Close() - _, err = file.WriteString(log) - if err != nil { - fmt.Printf("error writing in log file: %v", err.Error()) + fmt.Fprintf(os.Stderr, "error writing to log file: %v\n", err) + // TODO: do we need to terminate on log error? + // set err for now so that we don't spew errors + f.gotErr = true } } + +// HangUp closes current logfile handle and opens a new one +// typically needed for log rotations +func (f *FileLogger) HangUp() error { + err := f.f.Close() + if err != nil { + return fmt.Errorf("close log: %w", err) + } + + f.f, err = os.OpenFile(f.logfile, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) + if err != nil { + return fmt.Errorf("open log: %w", err) + } + + f.f.WriteString(fmt.Sprintf("log starts %v\n", time.Now())) + + return nil +} + +// Shutdown closes logfile handle +func (f *FileLogger) Shutdown() error { + return f.f.Close() +} diff --git a/s3log/webhook.go b/s3log/webhook.go index cd5a8735..4fcf31be 100644 --- a/s3log/webhook.go +++ b/s3log/webhook.go @@ -21,6 +21,7 @@ import ( "fmt" "net" "net/http" + "os" "strings" "sync" "time" @@ -29,14 +30,15 @@ import ( "github.com/versity/versitygw/s3err" ) +// WebhookLogger is a webhook URL audit log type WebhookLogger struct { - LogFields mu sync.Mutex url string } var _ AuditLogger = &WebhookLogger{} +// InitWebhookLogger initializes audit logs to webhook URL func InitWebhookLogger(url string) (AuditLogger, error) { client := &http.Client{ Timeout: 3 * time.Second, @@ -44,7 +46,7 @@ func InitWebhookLogger(url string) (AuditLogger, error) { _, err := client.Post(url, "application/json", nil) if err != nil { if err, ok := err.(net.Error); ok && !err.Timeout() { - return nil, fmt.Errorf("unreachable webhook url") + return nil, fmt.Errorf("unreachable webhook url: %w", err) } } return &WebhookLogger{ @@ -52,10 +54,13 @@ func InitWebhookLogger(url string) (AuditLogger, error) { }, nil } +// Log sends log message to webhook func (wl *WebhookLogger) Log(ctx *fiber.Ctx, err error, body []byte, meta LogMeta) { wl.mu.Lock() defer wl.mu.Unlock() + lf := LogFields{} + access := "-" reqURI := ctx.Request().URI().String() path := strings.Split(ctx.Path(), "/") @@ -65,8 +70,8 @@ func (wl *WebhookLogger) Log(ctx *fiber.Ctx, err error, body []byte, meta LogMet startTime := ctx.Locals("startTime").(time.Time) tlsConnState := ctx.Context().TLSConnectionState() if tlsConnState != nil { - wl.CipherSuite = tls.CipherSuiteName(tlsConnState.CipherSuite) - wl.TLSVersion = getTLSVersionName(tlsConnState.Version) + lf.CipherSuite = tls.CipherSuiteName(tlsConnState.CipherSuite) + lf.TLSVersion = getTLSVersionName(tlsConnState.Version) } if err != nil { @@ -85,43 +90,43 @@ func (wl *WebhookLogger) Log(ctx *fiber.Ctx, err error, body []byte, meta LogMet access = ctx.Locals("access").(string) } - wl.BucketOwner = meta.BucketOwner - wl.Bucket = bucket - wl.Time = time.Now() - wl.RemoteIP = ctx.IP() - wl.Requester = access - wl.RequestID = genID() - wl.Operation = meta.Action - wl.Key = object - wl.RequestURI = reqURI - wl.HttpStatus = httpStatus - wl.ErrorCode = errorCode - wl.BytesSent = len(body) - wl.ObjectSize = meta.ObjectSize - wl.TotalTime = time.Since(startTime).Milliseconds() - wl.TurnAroundTime = time.Since(startTime).Milliseconds() - wl.Referer = ctx.Get("Referer") - wl.UserAgent = ctx.Get("User-Agent") - wl.VersionID = ctx.Query("versionId") - wl.HostID = ctx.Get("X-Amz-Id-2") - wl.SignatureVersion = "SigV4" - wl.AuthenticationType = "AuthHeader" - wl.HostHeader = fmt.Sprintf("s3.%v.amazonaws.com", ctx.Locals("region").(string)) - wl.AccessPointARN = fmt.Sprintf("arn:aws:s3:::%v", strings.Join(path, "/")) - wl.AclRequired = "Yes" + lf.BucketOwner = meta.BucketOwner + lf.Bucket = bucket + lf.Time = time.Now() + lf.RemoteIP = ctx.IP() + lf.Requester = access + lf.RequestID = genID() + lf.Operation = meta.Action + lf.Key = object + lf.RequestURI = reqURI + lf.HttpStatus = httpStatus + lf.ErrorCode = errorCode + lf.BytesSent = len(body) + lf.ObjectSize = meta.ObjectSize + lf.TotalTime = time.Since(startTime).Milliseconds() + lf.TurnAroundTime = time.Since(startTime).Milliseconds() + lf.Referer = ctx.Get("Referer") + lf.UserAgent = ctx.Get("User-Agent") + lf.VersionID = ctx.Query("versionId") + lf.HostID = ctx.Get("X-Amz-Id-2") + lf.SignatureVersion = "SigV4" + lf.AuthenticationType = "AuthHeader" + lf.HostHeader = fmt.Sprintf("s3.%v.amazonaws.com", ctx.Locals("region").(string)) + lf.AccessPointARN = fmt.Sprintf("arn:aws:s3:::%v", strings.Join(path, "/")) + lf.AclRequired = "Yes" - wl.sendLog() + wl.sendLog(lf) } -func (wl *WebhookLogger) sendLog() { - jsonLog, err := json.Marshal(wl) +func (wl *WebhookLogger) sendLog(lf LogFields) { + jsonLog, err := json.Marshal(lf) if err != nil { - fmt.Printf("\n failed to parse the log data: %v", err.Error()) + fmt.Fprintf(os.Stderr, "failed to parse the log data: %v\n", err.Error()) } req, err := http.NewRequest(http.MethodPost, wl.url, bytes.NewReader(jsonLog)) if err != nil { - fmt.Println(err) + fmt.Fprintln(os.Stderr, err) } req.Header.Set("Content-Type", "application/json; charset=utf-8") @@ -135,7 +140,17 @@ func makeRequest(req *http.Request) { _, err := client.Do(req) if err != nil { if err, ok := err.(net.Error); ok && !err.Timeout() { - fmt.Println("error sending the log to the specified url") + fmt.Fprintf(os.Stderr, "error sending webhook log: %v\n", err) } } } + +// HangUp does nothing for webhooks +func (wl *WebhookLogger) HangUp() error { + return nil +} + +// Shutdown does nothing for webhooks +func (wl *WebhookLogger) Shutdown() error { + return nil +}