3
0

Tweak & plug in stat logging

This commit is contained in:
Tomaž Jerman
2024-11-27 16:09:39 +01:00
parent 3fdaafd8a1
commit a99bf12d87
8 changed files with 580 additions and 50 deletions
+18
View File
@@ -115,6 +115,24 @@ func statRoles(rr ...*Role) (stats map[roleKind]int) {
return
}
func removedRoles(current []*Role, new ...*Role) (out []*Role) {
nx := map[uint64]bool{}
for _, n := range new {
nx[n.id] = true
}
for _, c := range current {
if nx[c.id] {
continue
}
out = append(out, c)
}
return
}
// compare list of session roles (ids) with preloaded roles and calculate the final list
func evalRoles(s Session, res Resource, preloadedRoles ...*Role) (out partRoles) {
var (
-10
View File
@@ -55,16 +55,6 @@ func eq(a, b *Rule) bool {
a.Operation == b.Operation
}
func ruleByRole(base RuleSet, roleID uint64) (out RuleSet) {
for _, r := range base {
if r.RoleID == roleID {
out = append(out, r)
}
}
return
}
// Dirty returns list of deleted (Access==Inherit) and changed (dirty) rules
func flushable(set RuleSet) (deletable, updatable, final RuleSet) {
deletable, updatable, final = RuleSet{}, RuleSet{}, RuleSet{}
+287 -22
View File
@@ -19,7 +19,10 @@ type (
mux sync.RWMutex
cfg Config
logger *zap.Logger
StatLogger statLogger
StatLogger *statsLogger
noop bool
noopAccess Access
usageCounter *usageCounter[string]
index *wrapperIndex
@@ -56,15 +59,11 @@ type (
// IndexFlushInterval states how often the index state should be flushed to the database
IndexFlushInterval time.Duration
// StatLogger provides the methods to log some performance metrices
StatLogger statLogger
// RuleStorage provides the methods to interact with rules
RuleStorage rbacRulesStore
// RoleStorage provides the methods to interact with roles
RoleStorage rbacRoleStore
// PullInitialRoles provides the initial set of roles we can use
PullInitialRoles func(ctx context.Context) ([]*types.Role, error)
// PullInitialState provides the initial index state
//
// The string slice provides index keys which should then be further processed
@@ -88,6 +87,35 @@ type (
op string
}
expCtrItem struct {
Key string `json:"key"`
Score float64 `json:"score"`
// added denotes when the item was added to the counter
Added time.Time `json:"added"`
// lastScored denotes when the item was last scored (either via decay or access)
LastScored time.Time `json:"lastScored"`
// lastAccess denotes when the item was last accessed, needed
LastAccess time.Time `json:"lastAccess"`
}
Stats struct {
CacheHits uint `json:"cacheHits"`
CacheMisses uint `json:"cacheMisses"`
CacheUpdates uint `json:"cacheUpdates"`
AvgTiming time.Duration `json:"avgTiming"`
MinTiming time.Duration `json:"minTiming"`
MaxTiming time.Duration `json:"maxTiming"`
IndexSize int `json:"indexSize"`
LastHits []string `json:"lastHits"`
LastMisses []string `json:"lastMisses"`
LastTimings []time.Duration `json:"lastTimings"`
Counters []expCtrItem `json:"counters"`
}
RuleFilter struct {
Resource []string
Operation string
@@ -138,21 +166,40 @@ func SetGlobal(svc *Service) {
gWrapper = svc
}
// RbacService initializes the wrapper service with all the required surrounding bits
func RbacService(ctx context.Context, l *zap.Logger, store rbacRulesStore, cc Config) (svc *Service, err error) {
cc = defaultWrapperConfig(cc)
// NoopSvc creates a blank RBAC service which always returns the stated access
func NoopSvc(access Access) (svc *Service) {
return &Service{
noop: true,
noopAccess: access,
}
}
// NewService initializes the wrapper service with all the required surrounding bits
func NewService(ctx context.Context, l *zap.Logger, store rbacRulesStore, cc Config) (svc *Service, err error) {
cc = defaultWrapperConfig(l, cc)
usageCounter := &usageCounter[string]{
incChan: make(chan string, 256),
incChan: make(chan string, 1024),
decayFactor: cc.DecayFactor,
decayInterval: cc.DecayInterval,
cleanupInterval: cc.CleanupInterval,
checkKeyInclusion: func(k string, role uint64) bool {
return strings.HasPrefix(k, strconv.FormatUint(role, 10))
},
}
sl := &statsLogger{
log: l.Named("rbac stats logger"),
cacheHitChan: make(chan statsWrap, 1024),
cacheMissChan: make(chan statsWrap, 1024),
timingChan: make(chan time.Duration, 1024),
}
svc = &Service{
cfg: cc,
StatLogger: cc.StatLogger,
StatLogger: sl,
logger: l,
usageCounter: usageCounter,
@@ -173,11 +220,12 @@ func RbacService(ctx context.Context, l *zap.Logger, store rbacRulesStore, cc Co
usageCounter.watch(ctx)
svc.watch(ctx)
sl.watch(ctx)
return
}
func defaultWrapperConfig(base Config) (out Config) {
func defaultWrapperConfig(l *zap.Logger, base Config) (out Config) {
out = base
// -1 disables partitioning so everything is pulled in memory
@@ -190,11 +238,6 @@ func defaultWrapperConfig(base Config) (out Config) {
out.FlushIndexState = func(ctx context.Context, s []string) error { return nil }
}
// Noop to avoid branching down the line
if base.StatLogger == nil {
out.StatLogger = &noopStatLogger{}
}
if base.ReindexStrategy == ReindexStrategyDefault {
out.ReindexStrategy = ReindexStrategyMemory
}
@@ -203,17 +246,29 @@ func defaultWrapperConfig(base Config) (out Config) {
}
// Can returns true if the given resource can be accessed
func (svc *Service) Can(ses Session, op string, res Resource) (ok bool, err error) {
func (svc *Service) Can(ses Session, op string, res Resource) (ok bool) {
ac, err := svc.Check(ses, op, res)
if err != nil {
return
svc.logger.Error("check failed with error",
zap.String("op", op),
zap.String("resource", res.RbacResource()),
zap.Error(err),
)
return false
}
return ac == Allow, nil
return ac == Allow
}
// Check returns the RBAC evaluation of the resource access
func (svc *Service) Check(ses Session, op string, res Resource) (a Access, err error) {
if svc.noop {
svc.logger.Debug(fmt.Sprintf("check bypass %v %v %v: %v", ses, op, res, svc.noopAccess))
return svc.noopAccess, nil
}
svc.logger.Debug(fmt.Sprintf("check %v %v %v", ses, op, res))
if hasWildcards(res.RbacResource()) {
// prevent use of wildcard resources for checking permissions
return Inherit, nil
@@ -320,6 +375,34 @@ func (svc *Service) Grant(ctx context.Context, rules ...*Rule) (err error) {
return
}
func (svc *Service) Stats() (out Stats, err error) {
svc.usageCounter.lock.RLock()
defer svc.usageCounter.lock.RUnlock()
for k, itm := range svc.usageCounter.index {
out.Counters = append(out.Counters, expCtrItem{
Key: k,
Score: itm.score,
Added: itm.added,
LastScored: itm.lastScored,
LastAccess: itm.lastAccess,
})
}
out.CacheHits,
out.CacheMisses,
out.AvgTiming,
out.MinTiming,
out.MaxTiming,
out.LastHits,
out.LastMisses,
out.LastTimings = svc.StatLogger.Stats()
out.IndexSize = svc.index.getSize()
return
}
// AddRole adds an additional role after the service was initialized
func (svc *Service) AddRole(r *Role) {
svc.mux.Lock()
@@ -328,6 +411,50 @@ func (svc *Service) AddRole(r *Role) {
svc.roles = append(svc.roles, r)
}
func (svc *Service) UpdateRoles(rr ...*Role) {
svc.mux.Lock()
defer svc.mux.Unlock()
stats := statRoles(rr...)
svc.logger.Debug(
"updating roles",
zap.Int("before", len(svc.roles)),
zap.Int("after", len(rr)),
zap.Int("bypass", stats[BypassRole]),
zap.Int("context", stats[ContextRole]),
zap.Int("common", stats[CommonRole]),
zap.Int("authenticated", stats[AuthenticatedRole]),
zap.Int("anonymous", stats[AnonymousRole]),
)
removed := removedRoles(svc.roles, rr...)
svc.cleanupCounter(removed...)
// @todo log update stats?
svc.roles = rr
}
// FindRulesByRoleID returns all RBAC rules that belong to a role
func (svc *Service) FindRulesByRoleID(ctx context.Context, roleID uint64) (rr RuleSet, err error) {
aux, _, err := svc.RuleStorage.SearchRbacRules(ctx, RuleFilter{
RoleID: roleID,
})
if err != nil {
return
}
for _, x := range aux {
rr = append(rr, &Rule{
RoleID: x.RoleID,
Resource: x.Resource,
Operation: x.Operation,
Access: x.Access,
})
}
return
}
// Remove role removes the role from the service
//
// @todo this won't clean out the removed rules until the next reload
@@ -354,6 +481,30 @@ func (svc *Service) IndexSize() int {
return svc.index.getSize()
}
// SignificantRoles returns two list of significant roles.
//
// See sigRoles on rules for more details
func (svc *Service) SignificantRoles(ctx context.Context, res Resource, op string) (aRR, dRR []uint64, err error) {
svc.mux.RLock()
defer svc.mux.RUnlock()
aux, _, err := svc.RuleStorage.SearchRbacRules(ctx, RuleFilter{
Resource: []string{res.RbacResource()},
Operation: op,
})
if err != nil {
return
}
aRR, dRR = aux.sigRoles(res.RbacResource(), op)
return
}
func (svc *Service) Rules(ctx context.Context) (out RuleSet, err error) {
out, _, err = svc.RuleStorage.SearchRbacRules(ctx, RuleFilter{})
return
}
// Clear cleans out all the data
func (svc *Service) Clear() {
svc.usageCounter = nil
@@ -391,11 +542,14 @@ func (svc *Service) check(ctx context.Context, rolesByKind partRoles, op, res st
}
// @todo should we cache this for n seconds? just in case it's going to happen again soon?
st.unindexedRules, err = svc.pullUnindexed(ctx, st.unindexedRoles, op, res)
var timing time.Duration
st.unindexedRules, timing, err = svc.pullUnindexed(ctx, st.unindexedRoles, op, res)
if err != nil {
return Inherit, err
}
svc.logDbTiming(timing)
a, err = svc.evaluate(
[]roleKind{ContextRole, CommonRole, AuthenticatedRole, AnonymousRole},
trace,
@@ -518,12 +672,17 @@ func (svc *Service) flush(ctx context.Context, rules ...*Rule) (err error) {
return
}
func (svc *Service) pullUnindexed(ctx context.Context, unindexed partRoles, op, res string) (out [5]map[uint64][]*Rule, err error) {
func (svc *Service) pullUnindexed(ctx context.Context, unindexed partRoles, op, res string) (out [5]map[uint64][]*Rule, timing time.Duration, err error) {
resPerm := make([]string, 0, 8)
resPerm = append(resPerm, res)
// Get all the resource permissions
// @todo get permissions for parent resources; this will probs be some lookup table
now := time.Now()
defer func() {
timing = time.Since(now)
}()
rr := strings.Split(res, "/")
for i := len(rr) - 1; i >= 0; i-- {
rr[i] = "*"
@@ -589,8 +748,25 @@ func (svc *Service) pullRules(ctx context.Context, role uint64, resource string)
return
}
func (svc *Service) ReloadRoles(ctx context.Context) (err error) {
svc.mux.Lock()
defer svc.mux.Unlock()
crt := svc.roles
svc.roles, err = svc.loadRoles(ctx)
if err != nil {
return
}
rmd := removedRoles(crt, svc.roles...)
svc.cleanupCounter(rmd...)
return
}
func (svc *Service) loadRoles(ctx context.Context) (out []*Role, err error) {
auxRoles, err := svc.cfg.PullInitialRoles(ctx)
auxRoles, _, err := svc.cfg.RoleStorage.SearchRoles(ctx, types.RoleFilter{})
if err != nil {
return
}
@@ -661,10 +837,18 @@ func (svc *Service) segmentRoles(roles partRoles, resource string) (indexed, uni
for k, rg := range roles {
for r := range rg {
if svc.index.isIndexed(r, resource) {
if indexed[k] == nil {
indexed[k] = make(map[uint64]bool)
}
indexed[k][r] = true
continue
}
if unindexed[k] == nil {
unindexed[k] = make(map[uint64]bool)
}
unindexed[k][r] = true
}
}
@@ -719,6 +903,14 @@ func (svc *Service) incCounter(roles partRoles, res Resource) {
}
}
func (svc *Service) cleanupCounter(roles ...*Role) {
if svc.cfg.Synchronous {
svc.cleanupCounterSync(roles...)
} else {
svc.cleanupCounterAsync(roles...)
}
}
func (svc *Service) incCounterSync(roles partRoles, res Resource) {
for _, rr := range roles {
for r := range rr {
@@ -735,6 +927,18 @@ func (svc *Service) incCounterAsync(roles partRoles, res Resource) {
}
}
func (svc *Service) cleanupCounterSync(roles ...*Role) {
for _, r := range roles {
gWrapper.usageCounter.cleanRoleKeys(r.id)
}
}
func (svc *Service) cleanupCounterAsync(roles ...*Role) {
for _, r := range roles {
svc.usageCounter.rmChan <- r.id
}
}
func (svc *Service) updateWrapperIndex(ctx context.Context) (err error) {
switch svc.cfg.ReindexStrategy {
case ReindexStrategyMemory:
@@ -835,8 +1039,31 @@ func (svc *Service) swapIndexes(ctx context.Context, auxIndex *wrapperIndex) {
}
// Performance monitoring
func (svc *Service) logDbTiming(timing time.Duration) {
if svc.cfg.Synchronous {
svc.logAccessSync(timing)
} else {
svc.logAccessAsync(timing)
}
}
func (svc *Service) logAccessSync(timing time.Duration) {
svc.StatLogger.Timing(timing)
}
func (svc *Service) logAccessAsync(timing time.Duration) {
svc.StatLogger.timingChan <- timing
}
func (svc *Service) logCachePerformance(hits, misses partRoles, resource, op string) {
if svc.cfg.Synchronous {
svc.logCachePerformanceSync(hits, misses, resource, op)
} else {
svc.logCachePerformanceAsync(hits, misses, resource, op)
}
}
func (svc *Service) logCachePerformanceSync(hits, misses partRoles, resource, op string) {
{
rls := make([]uint64, 0, 4)
@@ -866,6 +1093,44 @@ func (svc *Service) logCachePerformance(hits, misses partRoles, resource, op str
}
}
func (svc *Service) logCachePerformanceAsync(hits, misses partRoles, resource, op string) {
// Hits
{
rls := make([]uint64, 0, 4)
for _, rr := range hits {
for r := range rr {
rls = append(rls, r)
}
}
if len(rls) > 0 {
svc.StatLogger.cacheHitChan <- statsWrap{
roles: rls,
resource: resource, op: op,
}
}
}
// Misses
{
rls := make([]uint64, 0, 4)
for _, rr := range misses {
for r := range rr {
rls = append(rls, r)
}
}
if len(rls) > 0 {
svc.StatLogger.cacheMissChan <- statsWrap{
roles: rls,
resource: resource, op: op,
}
}
}
}
// Debugger stuff
func (svc *Service) DebuggerSetIndex(role uint64, resource string, rules ...*Rule) (err error) {
+154 -18
View File
@@ -1,28 +1,164 @@
package rbac
type (
// @todo :)
stats struct {
cacheHitChan chan string
cacheMissChan chan string
import (
"context"
"fmt"
"sync"
"time"
// cacheHits
}
noopStatLogger struct{}
"github.com/cortezaproject/corteza/server/pkg/slice"
"go.uber.org/zap"
)
func Statser() {
type (
statsLogger struct {
lock sync.RWMutex
log *zap.Logger
// Channels for async comms
cacheHitChan chan statsWrap
cacheMissChan chan statsWrap
timingChan chan time.Duration
// Counters
cacheHits uint
cacheMisses uint
cacheUpdates uint
avgTiming time.Duration
minTiming time.Duration
maxTiming time.Duration
// Track a limited set of things
// Using a circular buffer we can easily not consume too much data
lastHits *slice.Circular[string]
lastMisses *slice.Circular[string]
lastTimings *slice.Circular[time.Duration]
}
// statsWrap wraps the state to log
statsWrap struct {
roles []uint64
resource string
op string
}
)
// Stats returns the tracked stats
func (l *statsLogger) Stats() (cacheHit uint, cacheMiss uint, avgTiming, minTiming, maxTiming time.Duration, lastHits []string, lastMisses []string, lastTimings []time.Duration) {
l.lock.RLock()
defer l.lock.RUnlock()
return l.cacheHits,
l.cacheMisses,
l.avgTiming,
l.minTiming,
l.maxTiming,
l.lastHits.Slice(),
l.lastMisses.Slice(),
l.lastTimings.Slice()
}
func (l *stats) CacheHit([]uint64, string, string) {}
func (l *stats) CacheMiss([]uint64, string, string) {}
func (l *stats) CacheUpdate(in *Rule) {}
// Timing logs the giving duration
func (l *statsLogger) Timing(timing time.Duration) {
l.lock.Lock()
defer l.lock.Unlock()
// Noop
l.log.Info("record timing", zap.Duration("timing", timing))
func (l *noopStatLogger) CacheHit([]uint64, string, string) {}
func (l *noopStatLogger) CacheMiss([]uint64, string, string) {}
func (l *noopStatLogger) CacheUpdate(in *Rule) {}
{
l.avgTiming = (l.avgTiming + timing) / 2
}
{
if l.minTiming == 0 {
l.minTiming = timing
}
if timing < l.minTiming {
l.minTiming = timing
}
}
{
if l.maxTiming == 0 {
l.maxTiming = timing
}
if timing > l.maxTiming {
l.maxTiming = timing
}
}
{
if l.lastTimings == nil {
l.lastTimings = slice.NewCircular[time.Duration](500)
}
l.lastTimings.Add(timing)
}
}
func (l *statsLogger) CacheHit(roles []uint64, resource string, op string) {
l.lock.Lock()
defer l.lock.Unlock()
l.log.Info("cache hit", zap.Any("roles", roles), zap.String("resource", resource), zap.String("op", op))
l.cacheHits++
if l.lastHits == nil {
l.lastHits = slice.NewCircular[string](10000)
}
l.lastHits.Add(l.strfEntry(roles, resource, op))
}
func (l *statsLogger) CacheMiss(roles []uint64, resource string, op string) {
l.lock.Lock()
defer l.lock.Unlock()
l.log.Info("cache miss", zap.Any("roles", roles), zap.String("resource", resource), zap.String("op", op))
l.cacheMisses++
if l.lastMisses == nil {
l.lastMisses = slice.NewCircular[string](10000)
}
l.lastMisses.Add(l.strfEntry(roles, resource, op))
}
func (l *statsLogger) CacheUpdate(in *Rule) {
l.lock.Lock()
defer l.lock.Unlock()
l.log.Info("cache update", zap.Any("rule", in))
l.cacheUpdates++
}
// // // // // // // // // // // // // // // // // // // // // // // // //
// Utils
func (l *statsLogger) strfEntry(roles []uint64, resource string, op string) string {
return fmt.Sprintf("%v %s %s", roles, op, resource)
}
func (l *statsLogger) watch(ctx context.Context) {
t := time.NewTicker(time.Minute * 5)
go func() {
for {
select {
case <-t.C:
l.log.Info("stats logger tick")
case rs := <-l.cacheMissChan:
l.CacheMiss(rs.roles, rs.resource, rs.op)
case rs := <-l.cacheHitChan:
l.CacheHit(rs.roles, rs.resource, rs.op)
case tt := <-l.timingChan:
l.Timing(tt)
case <-ctx.Done():
l.log.Info("terminating watcher")
}
}
}()
}
+20
View File
@@ -24,6 +24,10 @@ type (
// incChan sends instructions to the counter re. key K increment
incChan chan K
rmChan chan uint64
checkKeyInclusion func(k K, role uint64) bool
// decayInterval denotes in what interval the decay factor should apply
decayInterval time.Duration
// cleanupInterval denotes in what interval counter evicts stuff
@@ -82,6 +86,19 @@ func (svc *usageCounter[K]) evict() (out []K) {
return out
}
func (svc *usageCounter[K]) cleanRoleKeys(role uint64) {
svc.lock.Lock()
defer svc.lock.Unlock()
for k := range svc.index {
if !svc.checkKeyInclusion(k, role) {
continue
}
delete(svc.index, k)
}
}
// decay applies the specified decay factor to the cache items
func (svc *usageCounter[K]) decay() {
svc.lock.Lock()
@@ -194,6 +211,9 @@ func (svc *usageCounter[K]) watch(ctx context.Context) {
case key := <-svc.incChan:
svc.inc(key)
case role := <-svc.rmChan:
svc.cleanRoleKeys(role)
}
}
}()
+55
View File
@@ -0,0 +1,55 @@
package slice
type (
Circular[V any] struct {
size int
slc []V
head int
cycled bool
}
)
func NewCircular[V any](size int) *Circular[V] {
return &Circular[V]{
slc: make([]V, size),
size: size,
}
}
func (cs *Circular[V]) Add(v V) {
if cs.head >= cs.size {
cs.head = 0
cs.cycled = true
}
cs.slc[cs.head] = v
cs.head++
}
func (cs *Circular[V]) Slice() (out []V) {
if cs == nil {
return
}
if !cs.cycled {
return cs.sliceUncycled()
}
return cs.sliceCycled()
}
func (cs *Circular[V]) sliceUncycled() (out []V) {
for i := 0; i < cs.head; i++ {
out = append(out, cs.slc[i])
}
return
}
func (cs *Circular[V]) sliceCycled() (out []V) {
for i := 0; i < cs.size; i++ {
xo := (cs.head + i) % cs.size
out = append(out, cs.slc[xo])
}
return
}
+37
View File
@@ -0,0 +1,37 @@
package slice
import (
"testing"
"github.com/stretchr/testify/require"
)
func TestCycleSlice(t *testing.T) {
req := require.New(t)
cc := NewCircular[int](5)
cc.Add(1)
req.Equal([]int{1}, cc.Slice())
cc.Add(2)
cc.Add(3)
req.Equal([]int{1, 2, 3}, cc.Slice())
cc.Add(4)
cc.Add(5)
req.Equal([]int{1, 2, 3, 4, 5}, cc.Slice())
cc.Add(6)
req.Equal([]int{2, 3, 4, 5, 6}, cc.Slice())
cc.Add(7)
cc.Add(8)
cc.Add(9)
cc.Add(10)
req.Equal([]int{6, 7, 8, 9, 10}, cc.Slice())
cc.Add(11)
cc.Add(12)
req.Equal([]int{8, 9, 10, 11, 12}, cc.Slice())
}
+9
View File
@@ -6,6 +6,7 @@ import (
"github.com/cortezaproject/corteza/server/store"
"github.com/cortezaproject/corteza/server/pkg/actionlog"
"github.com/cortezaproject/corteza/server/pkg/rbac"
"github.com/cortezaproject/corteza/server/system/types"
)
@@ -26,6 +27,8 @@ type (
Users *types.UserMetrics `json:"users"`
Roles *types.RoleMetrics `json:"roles"`
Applications *types.ApplicationMetrics `json:"applications"`
Rbac rbac.Stats `json:"rbac"`
}
)
@@ -62,6 +65,12 @@ func (svc statistics) Metrics(ctx context.Context) (rval *StatisticsMetricsPaylo
}
}
// @todo rbac
rval.Rbac, err = rbac.Global().Stats()
if err != nil {
return err
}
return nil
}()