From 97628e69c9f8896ee774d79ba959492bf61b47e7 Mon Sep 17 00:00:00 2001 From: Roxana Nemulescu Date: Tue, 25 May 2021 11:38:21 +0300 Subject: [PATCH] logs: add an audit log for API calls with unit tests resolves #178 --- examples/config-example.json | 3 +- examples/config-example.yaml | 2 + pkg/api/config.go | 1 + pkg/api/controller.go | 19 +- pkg/log/log.go | 93 ++++++++- pkg/log/log_test.go | 386 +++++++++++++++++++++++++++++++++++ 6 files changed, 500 insertions(+), 4 deletions(-) create mode 100644 pkg/log/log_test.go diff --git a/examples/config-example.json b/examples/config-example.json index 70b66348..a26a61e3 100644 --- a/examples/config-example.json +++ b/examples/config-example.json @@ -32,6 +32,7 @@ }, "log":{ "level":"debug", - "output":"/tmp/zot.log" + "output":"/tmp/zot.log", + "audit": "/tmp/zot-audit.log" } } diff --git a/examples/config-example.yaml b/examples/config-example.yaml index ceb67161..0a3741b7 100644 --- a/examples/config-example.yaml +++ b/examples/config-example.yaml @@ -28,3 +28,5 @@ http: log: level: debug output: /tmp/zot.log + audit: /tmp/zot-audit.log + diff --git a/pkg/api/config.go b/pkg/api/config.go index ef0a546e..d91f144c 100644 --- a/pkg/api/config.go +++ b/pkg/api/config.go @@ -70,6 +70,7 @@ type LDAPConfig struct { type LogConfig struct { Level string Output string + Audit string } type GlobalStorageConfig struct { diff --git a/pkg/api/controller.go b/pkg/api/controller.go index 3316906a..6af74671 100644 --- a/pkg/api/controller.go +++ b/pkg/api/controller.go @@ -26,11 +26,24 @@ type Controller struct { Router *mux.Router StoreController storage.StoreController Log log.Logger + Audit *log.Logger Server *http.Server } func NewController(config *Config) *Controller { - return &Controller{Config: config, Log: log.NewLogger(config.Log.Level, config.Log.Output)} + var controller Controller + + logger := log.NewLogger(config.Log.Level, config.Log.Output) + + controller.Config = config + controller.Log = logger + + if config.Log.Audit != "" { + audit := log.NewAuditLogger(config.Log.Level, config.Log.Audit) + controller.Audit = audit + } + + return &controller } func DefaultHeaders() mux.MiddlewareFunc { @@ -62,6 +75,10 @@ func (c *Controller) Run() error { handlers.RecoveryHandler(handlers.RecoveryLogger(c.Log), handlers.PrintRecoveryStack(false))) + if c.Audit != nil { + engine.Use(log.SessionAuditLogger(c.Audit)) + } + c.Router = engine c.Router.UseEncodedPath() diff --git a/pkg/log/log.go b/pkg/log/log.go index ea5eafa1..42932f16 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -1,8 +1,10 @@ package log import ( + "encoding/base64" "net/http" "os" + "strings" "time" "github.com/gorilla/mux" @@ -43,6 +45,28 @@ func NewLogger(level string, output string) Logger { return Logger{Logger: log.With().Caller().Timestamp().Logger()} } +func NewAuditLogger(level string, audit string) *Logger { + zerolog.TimeFieldFormat = time.RFC3339Nano + lvl, err := zerolog.ParseLevel(level) + + if err != nil { + panic(err) + } + + zerolog.SetGlobalLevel(lvl) + + var auditLog zerolog.Logger + + auditFile, err := os.OpenFile(audit, os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0600) + if err != nil { + panic(err) + } + + auditLog = zerolog.New(auditFile) + + return &Logger{Logger: auditLog.With().Timestamp().Logger()} +} + type statusWriter struct { http.ResponseWriter status int @@ -65,6 +89,7 @@ func (w *statusWriter) Write(b []byte) (int, error) { return n, err } +// SessionLogger logs session details. func SessionLogger(log Logger) mux.MiddlewareFunc { l := log.With().Str("module", "http").Logger() @@ -90,8 +115,22 @@ func SessionLogger(log Logger) mux.MiddlewareFunc { clientIP := r.RemoteAddr method := r.Method headers := map[string][]string{} + username := "" + log := l.Info() for key, value := range r.Header { if key == "Authorization" { // anonymize from logs + s := strings.SplitN(value[0], " ", 2) + if len(s) == 2 && strings.EqualFold(s[0], "basic") { + b, err := base64.StdEncoding.DecodeString(s[1]) + if err == nil { + pair := strings.SplitN(string(b), ":", 2) + // nolint:gomnd + if len(pair) == 2 { + username = pair[0] + log = log.Str("username", username) + } + } + } value = []string{"******"} } headers[key] = value @@ -102,8 +141,7 @@ func SessionLogger(log Logger) mux.MiddlewareFunc { path = path + "?" + raw } - l.Info(). - Str("clientIP", clientIP). + log.Str("clientIP", clientIP). Str("method", method). Str("path", path). Int("statusCode", statusCode). @@ -114,3 +152,54 @@ func SessionLogger(log Logger) mux.MiddlewareFunc { }) } } + +func SessionAuditLogger(audit *Logger) mux.MiddlewareFunc { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + path := r.URL.Path + raw := r.URL.RawQuery + + sw := statusWriter{ResponseWriter: w} + + // Process request + next.ServeHTTP(&sw, r) + + clientIP := r.RemoteAddr + method := r.Method + username := "" + + for key, value := range r.Header { + if key == "Authorization" { // anonymize from logs + s := strings.SplitN(value[0], " ", 2) + if len(s) == 2 && strings.EqualFold(s[0], "basic") { + b, err := base64.StdEncoding.DecodeString(s[1]) + if err == nil { + pair := strings.SplitN(string(b), ":", 2) + // nolint:gomnd + if len(pair) == 2 { + username = pair[0] + } + } + } + } + } + + statusCode := sw.status + if raw != "" { + path = path + "?" + raw + } + + if (method == http.MethodPost || method == http.MethodPut || + method == http.MethodPatch || method == http.MethodDelete) && + (statusCode == http.StatusOK || statusCode == http.StatusCreated || statusCode == http.StatusAccepted) { + audit.Info(). + Str("clientIP", clientIP). + Str("subject", username). + Str("action", method). + Str("object", path). + Int("status", statusCode). + Msg("HTTP API Audit") + } + }) + } +} diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go new file mode 100644 index 00000000..dc767406 --- /dev/null +++ b/pkg/log/log_test.go @@ -0,0 +1,386 @@ +// +build extended + +package log_test + +import ( + "bytes" + "context" + "encoding/json" + "fmt" + "io" + "io/ioutil" + "net/http" + "os" + "path" + "strings" + "testing" + "time" + + "github.com/anuvu/zot/pkg/api" + godigest "github.com/opencontainers/go-digest" + . "github.com/smartystreets/goconvey/convey" + "gopkg.in/resty.v1" +) + +const ( + BaseURL = "http://127.0.0.1:8086" + SecurePort = "8086" + username = "test" + passphrase = "test" + ServerCert = "../../test/data/server.cert" + AuthorizedNamespace = "everyone/isallowed" + UnauthorizedNamespace = "fortknox/notallowed" +) + +type AuditLog struct { + Level string `json:"level"` + ClientIP string `json:"clientIP"` + Subject string `json:"subject"` + Action string `json:"action"` + Object string `json:"object"` + Status int `json:"status"` + Time string `json:"time"` + Message string `json:"message"` +} + +func makeHtpasswdFile() string { + f, err := ioutil.TempFile("", "htpasswd-") + if err != nil { + panic(err) + } + + // bcrypt(username="test", passwd="test") + content := []byte("test:$2y$05$hlbSXDp6hzDLu6VwACS39ORvVRpr3OMR4RlJ31jtlaOEGnPjKZI1m\n") + if err := ioutil.WriteFile(f.Name(), content, 0600); err != nil { + panic(err) + } + + return f.Name() +} + +func copyFiles(sourceDir string, destDir string) error { + sourceMeta, err := os.Stat(sourceDir) + if err != nil { + return err + } + + if err := os.MkdirAll(destDir, sourceMeta.Mode()); err != nil { + return err + } + + files, err := ioutil.ReadDir(sourceDir) + if err != nil { + return err + } + + for _, file := range files { + sourceFilePath := path.Join(sourceDir, file.Name()) + destFilePath := path.Join(destDir, file.Name()) + + if file.IsDir() { + if err = copyFiles(sourceFilePath, destFilePath); err != nil { + return err + } + } else { + sourceFile, err := os.Open(sourceFilePath) + if err != nil { + return err + } + defer sourceFile.Close() + + destFile, err := os.Create(destFilePath) + if err != nil { + return err + } + defer destFile.Close() + + if _, err = io.Copy(destFile, sourceFile); err != nil { + return err + } + } + } + + return nil +} + +func Location(baseURL string, resp *resty.Response) string { + // For some API responses, the Location header is set and is supposed to + // indicate an opaque value. However, it is not clear if this value is an + // absolute URL (https://server:port/v2/...) or just a path (/v2/...) + // zot implements the latter as per the spec, but some registries appear to + // return the former - this needs to be clarified + loc := resp.Header().Get("Location") + if loc[0] == '/' { + return baseURL + loc + } + + return loc +} + +func TestAuditLogMessages(t *testing.T) { + Convey("Make a new controller", t, func() { + dir, err := ioutil.TempDir("", "oci-repo-test") + if err != nil { + panic(err) + } + defer os.RemoveAll(dir) + err = copyFiles("../../test/data", dir) + if err != nil { + panic(err) + } + + config := api.NewConfig() + + outputPath := dir + "/zot.log" + auditPath := dir + "/zot-audit.log" + config.Log = &api.LogConfig{Level: "debug", Output: outputPath, Audit: auditPath} + + config.HTTP.Port = SecurePort + + htpasswdPath := makeHtpasswdFile() + defer os.Remove(htpasswdPath) + config.HTTP.Auth = &api.AuthConfig{ + HTPasswd: api.AuthHTPasswd{ + Path: htpasswdPath, + }, + } + + c := api.NewController(config) + c.Config.Storage.RootDirectory = dir + go func() { + // this blocks + if err := c.Run(); err != nil { + return + } + }() + + // wait till ready + for { + _, err := resty.R().Get(BaseURL) + if err == nil { + break + } + time.Sleep(100 * time.Millisecond) + } + + defer func() { + ctx := context.Background() + _ = c.Server.Shutdown(ctx) + }() + + Convey("Open auditLog file", func() { + auditFile, err := os.Open(auditPath) + if err != nil { + t.Log("Cannot open file") + panic(err) + } + defer auditFile.Close() + + Convey("Test GET request", func() { + resp, err := resty.R().SetBasicAuth(username, passphrase). + Get(BaseURL + "/v2/") + So(err, ShouldBeNil) + So(resp, ShouldNotBeNil) + So(resp.StatusCode(), ShouldEqual, http.StatusOK) + + byteValue, _ := ioutil.ReadAll(auditFile) + So(len(byteValue), ShouldEqual, 0) + }) + + Convey("Test POST request", func() { + path := "/v2/" + AuthorizedNamespace + "/blobs/uploads/" + resp, err := resty.R().SetBasicAuth(username, passphrase). + Post(BaseURL + path) + So(err, ShouldBeNil) + So(resp, ShouldNotBeNil) + So(resp.StatusCode(), ShouldEqual, http.StatusAccepted) + + // wait until the file is populated + byteValue, _ := ioutil.ReadAll(auditFile) + for { + if len(byteValue) != 0 { + break + } + time.Sleep(100 * time.Millisecond) + byteValue, _ = ioutil.ReadAll(auditFile) + } + + var auditLog AuditLog + err = json.Unmarshal(byteValue, &auditLog) + if err != nil { + panic(err) + } + + So(auditLog.Subject, ShouldEqual, username) + So(auditLog.Action, ShouldEqual, http.MethodPost) + So(auditLog.Status, ShouldEqual, http.StatusAccepted) + So(auditLog.Object, ShouldEqual, path) + }) + + Convey("Test PUT and DELETE request", func() { + // create upload + path := "/v2/repo/blobs/uploads/" + resp, err := resty.R().SetBasicAuth(username, passphrase).Post(BaseURL + path) + So(err, ShouldBeNil) + So(resp.StatusCode(), ShouldEqual, http.StatusAccepted) + loc := Location(BaseURL, resp) + So(loc, ShouldNotBeEmpty) + location := resp.Header().Get("Location") + So(location, ShouldNotBeEmpty) + + // wait until the file is populated + byteValue, _ := ioutil.ReadAll(auditFile) + for { + if len(byteValue) != 0 { + break + } + time.Sleep(100 * time.Millisecond) + byteValue, _ = ioutil.ReadAll(auditFile) + } + + var auditLog AuditLog + err = json.Unmarshal(byteValue, &auditLog) + if err != nil { + panic(err) + } + + So(auditLog.Subject, ShouldEqual, username) + So(auditLog.Action, ShouldEqual, http.MethodPost) + So(auditLog.Status, ShouldEqual, http.StatusAccepted) + So(auditLog.Object, ShouldEqual, path) + + content := []byte("this is a blob") + digest := godigest.FromBytes(content) + So(digest, ShouldNotBeNil) + + // blob upload + resp, err = resty.R().SetQueryParam("digest", digest.String()). + SetBasicAuth(username, passphrase). + SetHeader("Content-Type", "application/octet-stream").SetBody(content).Put(loc) + So(err, ShouldBeNil) + So(resp.StatusCode(), ShouldEqual, http.StatusCreated) + blobLoc := Location(BaseURL, resp) + So(blobLoc, ShouldNotBeEmpty) + So(resp.Header().Get(api.DistContentDigestKey), ShouldNotBeEmpty) + + // wait until the file is populated + byteValue, _ = ioutil.ReadAll(auditFile) + for { + if len(byteValue) != 0 { + break + } + time.Sleep(100 * time.Millisecond) + byteValue, _ = ioutil.ReadAll(auditFile) + } + + err = json.Unmarshal(byteValue, &auditLog) + if err != nil { + panic(err) + } + + So(auditLog.Subject, ShouldEqual, username) + So(auditLog.Action, ShouldEqual, http.MethodPut) + So(auditLog.Status, ShouldEqual, http.StatusCreated) + + putPath := location + "?digest=" + strings.ReplaceAll(digest.String(), ":", "%3A") + So(auditLog.Object, ShouldEqual, putPath) + + // delete this blob + resp, err = resty.R().SetBasicAuth(username, passphrase).Delete(blobLoc) + So(err, ShouldBeNil) + So(resp.StatusCode(), ShouldEqual, http.StatusAccepted) + So(resp.Header().Get("Content-Length"), ShouldEqual, "0") + + // wait until the file is populated + byteValue, _ = ioutil.ReadAll(auditFile) + for { + if len(byteValue) != 0 { + break + } + time.Sleep(100 * time.Millisecond) + byteValue, _ = ioutil.ReadAll(auditFile) + } + + err = json.Unmarshal(byteValue, &auditLog) + if err != nil { + panic(err) + } + + So(auditLog.Subject, ShouldEqual, username) + So(auditLog.Action, ShouldEqual, http.MethodDelete) + So(auditLog.Status, ShouldEqual, http.StatusAccepted) + + deletePath := strings.ReplaceAll(path, "uploads/", digest.String()) + So(auditLog.Object, ShouldEqual, deletePath) + }) + + Convey("Test PATCH request", func() { + path := "/v2/repo/blobs/uploads/" + resp, err := resty.R().SetBasicAuth(username, passphrase).Post(BaseURL + path) + So(err, ShouldBeNil) + So(resp.StatusCode(), ShouldEqual, http.StatusAccepted) + loc := Location(BaseURL, resp) + So(loc, ShouldNotBeEmpty) + location := resp.Header().Get("Location") + So(location, ShouldNotBeEmpty) + + // wait until the file is populated + byteValue, _ := ioutil.ReadAll(auditFile) + for { + if len(byteValue) != 0 { + break + } + time.Sleep(100 * time.Millisecond) + byteValue, _ = ioutil.ReadAll(auditFile) + } + + var auditLog AuditLog + err = json.Unmarshal(byteValue, &auditLog) + if err != nil { + panic(err) + } + + So(auditLog.Subject, ShouldEqual, username) + So(auditLog.Action, ShouldEqual, http.MethodPost) + So(auditLog.Status, ShouldEqual, http.StatusAccepted) + So(auditLog.Object, ShouldEqual, path) + + var buf bytes.Buffer + chunk := []byte("this is a chunk") + n, err := buf.Write(chunk) + So(n, ShouldEqual, len(chunk)) + So(err, ShouldBeNil) + + // write a chunk + contentRange := fmt.Sprintf("%d-%d", 0, len(chunk)-1) + resp, err = resty.R().SetBasicAuth(username, passphrase). + SetHeader("Content-Type", "application/octet-stream"). + SetHeader("Content-Range", contentRange).SetBody(chunk).Patch(loc) + So(err, ShouldBeNil) + So(resp.StatusCode(), ShouldEqual, http.StatusAccepted) + + // wait until the file is populated + byteValue, _ = ioutil.ReadAll(auditFile) + for { + if len(byteValue) != 0 { + break + } + time.Sleep(100 * time.Millisecond) + byteValue, _ = ioutil.ReadAll(auditFile) + } + + err = json.Unmarshal(byteValue, &auditLog) + if err != nil { + panic(err) + } + + So(auditLog.Subject, ShouldEqual, username) + So(auditLog.Action, ShouldEqual, http.MethodPatch) + So(auditLog.Status, ShouldEqual, http.StatusAccepted) + + patchPath := location + So(auditLog.Object, ShouldEqual, patchPath) + }) + }) + }) +}