logs: add an audit log for API calls with unit tests

resolves #178

examples/config-example.json

@@ -32,6 +32,7 @@
   },
   "log":{
     "level":"debug",
-    "output":"/tmp/zot.log"
+    "output":"/tmp/zot.log",
+    "audit": "/tmp/zot-audit.log"
   }
 }

examples/config-example.yaml

@@ -28,3 +28,5 @@ http:
 log:
   level: debug
   output: /tmp/zot.log
+  audit: /tmp/zot-audit.log
+

pkg/api/config.go

@@ -70,6 +70,7 @@ type LDAPConfig struct {
 type LogConfig struct {
 	Level  string
 	Output string
+	Audit  string
 }
 
 type GlobalStorageConfig struct {

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()
 

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().
+			log.Str("clientIP", clientIP).
-				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")
+			}
+		})
+	}
+}

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)
+			})
+		})
+	})
+}