Merge pull request #3 from eko/added-audit-logs

Added audit logs

Author: eko

README.md

@@ -24,13 +24,18 @@ You can use both Role-Based Acccess Control (RBAC) and Attribute-Based Access Co
 
 ✅  Reliable: Authz uses Authz itself for managing its own internal authorizations
 
+🔍  Audit: We log each check decisions and which policy matched
+
 ## How it works?
 
 Authorization is simple: a `principal` wants to make an `action` on a `resource`. That's it.
 
 Authz allows you to manage all the authorizations you want to manage. All of them, centralized in a single application.
 
-<h1 align="center"><img src="docs/architecture/howitworks.svg" alt="Authz" width="600"></h1>
+<picture>
+  <source media="(prefers-color-scheme: dark)" srcset="docs/architecture/howitworks.dark.svg">
+  <img alt="Text changing depending on mode. Light: 'So light!' Dark: 'So dark!'" src="docs/architecture/howitworks.svg">
+</picture>
 
 All you need to do is to host the backend server (a Go single binary), the frontend (static files) if you want it and use our SDKs.
 

backend/Makefile

@@ -50,6 +50,7 @@ test-mocks: ## Generate unit test mocks
 	mockgen -source=internal/event/dispatcher.go -destination=internal/event/dispatcher_mock.go -package=event
 	mockgen -source=internal/entity/manager/action.go -destination=internal/entity/manager/action_mock.go -package=manager
 	mockgen -source=internal/entity/manager/attribute.go -destination=internal/entity/manager/attribute_mock.go -package=manager
+	mockgen -source=internal/entity/manager/audit.go -destination=internal/entity/manager/audit_mock.go -package=manager
 	mockgen -source=internal/entity/manager/client.go -destination=internal/entity/manager/client_mock.go -package=manager
 	mockgen -source=internal/entity/manager/compiled.go -destination=internal/entity/manager/compiled_mock.go -package=manager
 	mockgen -source=internal/entity/manager/policy.go -destination=internal/entity/manager/policy_mock.go -package=manager

backend/README.md

@@ -26,7 +26,12 @@ Here are the available configuration options available as environment variable:
 
 | Property | Default value | Description |
 | -------- | ------------- | ----------- |
-| APP_STATS_FLUSH_DELAY | `5s` | Delay in which statistics will be batch into database |
+| APP_AUDIT_CLEAN_DAYS_TO_KEEP | `7` | Audit logs number of days to keep in database |
+| APP_AUDIT_CLEAN_DELAY | `1h` | Audit logs clean delay |
+| APP_AUDIT_FLUSH_DELAY | `3s` | Delay in which audit logs will be batch into database |
+| APP_STATS_CLEAN_DAYS_TO_KEEP | `30` | Statistics number of days to keep in database |
+| APP_STATS_CLEAN_DELAY | `1h` | Statistics clean delay |
+| APP_STATS_FLUSH_DELAY | `3s` | Delay in which statistics will be batch into database |
 | AUTH_ACCESS_TOKEN_DURATION | `6h` | Access token duration  |
 | AUTH_DOMAIN | `http://localhost:8080` | OAuth domain to be used  |
 | AUTH_JWT_SIGN_STRING | `4uthz-s3cr3t-valu3-pl3as3-ch4ng3!` | Default HMAC to use for JWT tokens |
@@ -48,8 +53,6 @@ Here are the available configuration options available as environment variable:
 | HTTP_SERVER_CORS_ALLOWED_METHODS | `GET,POST,PATCH,PUT,DELETE,HEAD,OPTIONS` | CORS allowed methods |
 | HTTP_SERVER_CORS_CACHE_MAX_AGE | `12h` | CORS cache max age value to be returned by server |
 | LOGGER_LEVEL | `INFO` | Log level, could be `DEBUG`, `INFO`, `WARN` or `ERROR` |
-| APP_STATS_CLEAN_DAYS_TO_KEEP | `30` | Statistics number of days to keep in database |
-| APP_STATS_CLEAN_DELAY | `1h` | Statistics clean delay |
 | USER_ADMIN_DEFAULT_PASSWORD | `changeme` | Default admin password updated on app launch |
 
 ## Tests

backend/cmd/main.go

@@ -4,6 +4,7 @@ import (
 	"context"
 
 	"github.com/eko/authz/backend/configs"
+	"github.com/eko/authz/backend/internal/audit"
 	"github.com/eko/authz/backend/internal/compile"
 	"github.com/eko/authz/backend/internal/database"
 	"github.com/eko/authz/backend/internal/entity"
@@ -25,6 +26,7 @@ func main() {
 		fx.Provide(context.Background),
 		internal_fx.Logger,
 
+		audit.FxModule(),
 		compile.FxModule(),
 		configs.FxModule(),
 		database.FxModule(),

backend/configs/app.go

@@ -3,6 +3,9 @@ package configs
 import "time"
 
 type App struct {
+	AuditCleanDelay            time.Duration `config:"app_audit_clean_delay"`
+	AuditCleanDaysToKeep       int           `config:"app_audit_clean_days_to_keep"`
+	AuditFlushDelay            time.Duration `config:"app_audit_flush_delay"`
 	DispatcherEventChannelSize int           `config:"dispatcher_event_channel_size"`
 	StatsCleanDelay            time.Duration `config:"app_stats_clean_delay"`
 	StatsCleanDaysToKeep       int           `config:"app_stats_clean_days_to_keep"`
@@ -11,6 +14,9 @@ type App struct {
 
 func newApp() *App {
 	return &App{
+		AuditCleanDelay:            1 * time.Hour,
+		AuditCleanDaysToKeep:       7,
+		AuditFlushDelay:            3 * time.Second,
 		DispatcherEventChannelSize: 10000,
 		StatsCleanDelay:            1 * time.Hour,
 		StatsCleanDaysToKeep:       30,

backend/internal/audit/cleaner.go

@@ -0,0 +1,70 @@
+package audit
+
+import (
+	"context"
+	lib_time "time"
+
+	"github.com/eko/authz/backend/configs"
+	"github.com/eko/authz/backend/internal/entity/manager"
+	"github.com/eko/authz/backend/internal/entity/repository"
+	"github.com/eko/authz/backend/internal/helper/time"
+	"go.uber.org/fx"
+	"golang.org/x/exp/slog"
+)
+
+type cleaner struct {
+	logger       *slog.Logger
+	clock        time.Clock
+	statsManager manager.Stats
+	cleanDelay   lib_time.Duration
+	daysToKeep   int
+}
+
+func NewCleaner(
+	cfg *configs.App,
+	logger *slog.Logger,
+	clock time.Clock,
+	statsManager manager.Stats,
+) *cleaner {
+	return &cleaner{
+		logger:       logger,
+		clock:        clock,
+		statsManager: statsManager,
+		cleanDelay:   cfg.StatsCleanDelay,
+		daysToKeep:   cfg.StatsCleanDaysToKeep,
+	}
+}
+
+func RunCleaner(lc fx.Lifecycle, cleaner *cleaner) {
+	ticker := lib_time.NewTicker(cleaner.cleanDelay)
+
+	lc.Append(fx.Hook{
+		OnStart: func(context.Context) error {
+			go func() {
+				for range ticker.C {
+					cleaner.logger.Info("Stats: cleaning stats older than 30 days")
+
+					if err := cleaner.statsManager.GetRepository().DeleteByFields(map[string]repository.FieldValue{
+						"date": {
+							Operator: "<=",
+							Value:    cleaner.clock.Now().AddDate(0, 0, -cleaner.daysToKeep),
+						},
+					}); err != nil {
+						cleaner.logger.Error("Stats: unable to clean stats", err)
+					}
+				}
+			}()
+
+			cleaner.logger.Info("Stats: cleaner started")
+
+			return nil
+		},
+		OnStop: func(_ context.Context) error {
+			ticker.Stop()
+
+			cleaner.logger.Info("Stats: cleaner stopped")
+
+			return nil
+		},
+	})
+}

backend/internal/audit/fx.go

@@ -0,0 +1,18 @@
+package audit
+
+import (
+	"go.uber.org/fx"
+)
+
+func FxModule() fx.Option {
+	return fx.Module("audit",
+		fx.Provide(
+			NewCleaner,
+			NewSubscriber,
+		),
+		fx.Invoke(
+			RunCleaner,
+			RunSubscriber,
+		),
+	)
+}

backend/internal/audit/subscriber.go

@@ -0,0 +1,103 @@
+package audit
+
+import (
+	"context"
+	"time"
+
+	"github.com/eko/authz/backend/configs"
+	"github.com/eko/authz/backend/internal/entity/manager"
+	"github.com/eko/authz/backend/internal/entity/model"
+	"github.com/eko/authz/backend/internal/event"
+	"github.com/eko/authz/backend/internal/helper/spooler"
+	"go.uber.org/fx"
+	"golang.org/x/exp/slog"
+)
+
+type subscriber struct {
+	logger          *slog.Logger
+	dispatcher      event.Dispatcher
+	auditManager    manager.Audit
+	auditFlushDelay time.Duration
+}
+
+func NewSubscriber(
+	cfg *configs.App,
+	logger *slog.Logger,
+	dispatcher event.Dispatcher,
+	auditManager manager.Audit,
+) *subscriber {
+	return &subscriber{
+		logger:          logger,
+		dispatcher:      dispatcher,
+		auditManager:    auditManager,
+		auditFlushDelay: cfg.AuditFlushDelay,
+	}
+}
+
+func (s *subscriber) subscribeToChecks(lc fx.Lifecycle) {
+	checkEventChan := s.dispatcher.Subscribe(event.EventTypeCheck)
+
+	lc.Append(fx.Hook{
+		OnStart: func(context.Context) error {
+			go s.handleCheckEvents(checkEventChan)
+
+			s.logger.Info("Audit: subscribed to event dispatchers")
+
+			return nil
+		},
+		OnStop: func(_ context.Context) error {
+			close(checkEventChan)
+
+			s.logger.Info("Audit: subscription to event dispatcher stopped")
+
+			return nil
+		},
+	})
+}
+
+func (s *subscriber) handleCheckEvents(eventChan chan *event.Event) {
+	var spooler = spooler.New(func(values []*event.Event) {
+		if len(values) == 0 {
+			return
+		}
+
+		var audits = []*model.Audit{}
+		var timestamp int64
+
+		for _, value := range values {
+			timestamp = value.Timestamp
+
+			checkEvent, ok := value.Data.(*event.CheckEvent)
+			if !ok {
+				continue
+			}
+
+			audit := &model.Audit{
+				Date:          time.Unix(timestamp, 0),
+				Principal:     checkEvent.Principal,
+				ResourceKind:  checkEvent.ResourceKind,
+				ResourceValue: checkEvent.ResourceValue,
+				Action:        checkEvent.Action,
+				IsAllowed:     checkEvent.IsAllowed,
+			}
+
+			if checkEvent.CompiledPilicy != nil {
+				audit.PolicyID = checkEvent.CompiledPilicy.PolicyID
+			}
+
+			audits = append(audits, audit)
+		}
+
+		if err := s.auditManager.BatchAdd(audits); err != nil {
+			s.logger.Error("Audit: unable to batch add audit events", err)
+		}
+	}, spooler.WithFlushInterval(s.auditFlushDelay))
+
+	for event := range eventChan {
+		spooler.Add(event)
+	}
+}
+
+func RunSubscriber(lc fx.Lifecycle, subscriber *subscriber) {
+	subscriber.subscribeToChecks(lc)
+}

backend/internal/audit/subscriber_test.go

@@ -0,0 +1,83 @@
+package audit
+
+import (
+	"testing"
+	"time"
+
+	"github.com/eko/authz/backend/configs"
+	"github.com/eko/authz/backend/internal/entity/manager"
+	"github.com/eko/authz/backend/internal/event"
+	"github.com/eko/authz/backend/internal/log"
+	"github.com/golang/mock/gomock"
+	"github.com/stretchr/testify/assert"
+	"golang.org/x/exp/slog"
+)
+
+func TestNewSubscriber(t *testing.T) {
+	// Given
+	ctrl := gomock.NewController(t)
+
+	cfg := &configs.App{
+		AuditFlushDelay: 10 * time.Millisecond,
+	}
+
+	logger := slog.New(log.NewNopHandler())
+
+	dispatcher := event.NewMockDispatcher(ctrl)
+
+	auditManager := manager.NewMockAudit(ctrl)
+
+	// When
+	subscriberInstance := NewSubscriber(cfg, logger, dispatcher, auditManager)
+
+	// Then
+	assert := assert.New(t)
+
+	assert.IsType(new(subscriber), subscriberInstance)
+
+	assert.Equal(logger, subscriberInstance.logger)
+	assert.Equal(dispatcher, subscriberInstance.dispatcher)
+	assert.Equal(auditManager, subscriberInstance.auditManager)
+	assert.Equal(cfg.AuditFlushDelay, subscriberInstance.auditFlushDelay)
+}
+
+func TestHandleCheckEvents(t *testing.T) {
+	// Given
+	ctrl := gomock.NewController(t)
+
+	cfg := &configs.App{
+		AuditFlushDelay: 10 * time.Millisecond,
+	}
+
+	logger := slog.New(log.NewNopHandler())
+
+	dispatcher := event.NewMockDispatcher(ctrl)
+
+	auditManager := manager.NewMockAudit(ctrl)
+	auditManager.EXPECT().BatchAdd(gomock.Len(3)).Times(1)
+
+	subscriber := NewSubscriber(cfg, logger, dispatcher, auditManager)
+
+	eventChan := make(chan *event.Event, 1)
+
+	// When - Then
+	go subscriber.handleCheckEvents(eventChan)
+
+	eventChan <- &event.Event{
+		Timestamp: 123456,
+		Data:      &event.CheckEvent{Principal: "user1", ResourceKind: "post", ResourceValue: "1", Action: "edit", IsAllowed: true},
+	}
+	eventChan <- &event.Event{
+		Timestamp: 123456,
+		Data:      &event.CheckEvent{Principal: "user1", ResourceKind: "post", ResourceValue: "2", Action: "edit", IsAllowed: false},
+	}
+	eventChan <- &event.Event{
+		Timestamp: 123457,
+		Data:      &event.CheckEvent{Principal: "user1", ResourceKind: "post", ResourceValue: "3", Action: "delete", IsAllowed: true},
+	}
+
+	close(eventChan)
+
+	// Wait 20ms to ensure the spool is triggered.
+	<-time.After(20 * time.Millisecond)
+}

backend/internal/database/database.go

@@ -50,6 +50,7 @@ func New(
 	if cfg.Driver == configs.DriverSqlite {
 		checkErr(slogLogger, db.AutoMigrate(model.Action{}))
 		checkErr(slogLogger, db.AutoMigrate(model.Attribute{}))
+		checkErr(slogLogger, db.AutoMigrate(model.Audit{}))
 		checkErr(slogLogger, db.AutoMigrate(model.Client{}))
 		checkErr(slogLogger, db.AutoMigrate(model.CompiledPolicy{}))
 		checkErr(slogLogger, db.AutoMigrate(model.Policy{}))

backend/internal/entity/fx.go

@@ -13,6 +13,7 @@ func FxModule() fx.Option {
 		fx.Provide(
 			manager.NewAction,
 			manager.NewAttribute,
+			manager.NewAudit,
 			manager.NewClient,
 			manager.NewCompiledPolicy,
 			manager.NewPolicy,
@@ -40,6 +41,15 @@ func FxModule() fx.Option {
 				return repository
 			},
 
+			// Audit
+			func(db *gorm.DB) repository.Base[model.Audit] {
+				return repository.New[model.Audit](db)
+			},
+
+			func(repository repository.Base[model.Audit]) manager.AuditRepository {
+				return repository
+			},
+
 			// Client
 			func(db *gorm.DB) repository.Base[model.Client] {
 				return repository.New[model.Client](db)