From cca560903975c16338df98dd22aaa1258aee7bc5 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sat, 13 Dec 2025 13:44:10 +0000 Subject: [PATCH 1/8] Initial plan From 2eaa341ca4a74e301fb05fd21d54a9d924391044 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sat, 13 Dec 2025 13:51:12 +0000 Subject: [PATCH 2/8] Add event-based logger interface and instrument Enforce method Co-authored-by: hsluoyz <3787410+hsluoyz@users.noreply.github.com> --- enforcer.go | 97 ++++++++++++++++++++++++++++++- log/default_event_logger.go | 53 +++++++++++++++++ log/event_logger.go | 111 ++++++++++++++++++++++++++++++++++++ 3 files changed, 258 insertions(+), 3 deletions(-) create mode 100644 log/default_event_logger.go create mode 100644 log/event_logger.go diff --git a/enforcer.go b/enforcer.go index 804c63148..b83a89da6 100644 --- a/enforcer.go +++ b/enforcer.go @@ -20,6 +20,7 @@ import ( "runtime/debug" "strings" "sync" + "time" "github.com/casbin/casbin/v3/effector" "github.com/casbin/casbin/v3/log" @@ -54,7 +55,9 @@ type Enforcer struct { autoNotifyDispatcher bool acceptJsonRequest bool - logger log.Logger + logger log.Logger + eventLogger log.EventLogger + subscribeCache map[log.EventType]bool } // EnforceContext is used as the first element of the parameter "rvals" in method "enforce". @@ -206,6 +209,47 @@ func (e *Enforcer) SetLogger(logger log.Logger) { } } +// SetEventLogger sets the event logger for the enforcer. +func (e *Enforcer) SetEventLogger(logger log.EventLogger) { + e.eventLogger = logger + e.updateSubscribeCache() +} + +// updateSubscribeCache updates the subscription cache for quick event type lookup +func (e *Enforcer) updateSubscribeCache() { + e.subscribeCache = make(map[log.EventType]bool) + + if e.eventLogger == nil { + return + } + + events := e.eventLogger.Subscribe() + if len(events) == 0 { + // Empty means subscribe to all + e.subscribeCache = nil + return + } + + for _, event := range events { + e.subscribeCache[event] = true + } +} + +// shouldLog checks if we should log this event type +func (e *Enforcer) shouldLog(eventType log.EventType) bool { + if e.eventLogger == nil || !e.eventLogger.IsEnabled() { + return false + } + + // nil cache means subscribe to all events + if e.subscribeCache == nil { + return true + } + + return e.subscribeCache[eventType] +} + + func (e *Enforcer) initialize() { e.rmMap = map[string]rbac.RoleManager{} e.condRmMap = map[string]rbac.ConditionalRoleManager{} @@ -610,6 +654,47 @@ func (e *Enforcer) invalidateMatcherMap() { // enforce use a custom matcher to decides whether a "subject" can access a "object" with the operation "action", input parameters are usually: (matcher, sub, obj, act), use model matcher by default when matcher is "". func (e *Enforcer) enforce(matcher string, explains *[]string, rvals ...interface{}) (ok bool, err error) { //nolint:funlen,cyclop,gocyclo // TODO: reduce function complexity + // Event logging setup + var entry *log.LogEntry + var handle *log.Handle + var logExplains [][]string + shouldLog := e.shouldLog(log.EventEnforce) + + if shouldLog { + entry = &log.LogEntry{ + Type: log.EventEnforce, + Timestamp: time.Now(), + Request: rvals, + Attributes: make(map[string]interface{}), + } + + // Parse request parameters + if len(rvals) >= 1 { + entry.Subject = toString(rvals[0]) + } + if len(rvals) >= 2 { + entry.Object = toString(rvals[1]) + } + if len(rvals) >= 3 { + entry.Action = toString(rvals[2]) + } + if len(rvals) >= 4 { + entry.Domain = toString(rvals[3]) + } + + handle = e.eventLogger.OnBeforeEvent(entry) + } + + defer func() { + if shouldLog && entry != nil && handle != nil { + entry.Duration = time.Since(entry.Timestamp) + entry.Allowed = ok + entry.Matched = logExplains + entry.Error = err + e.eventLogger.OnAfterEvent(handle, entry) + } + }() + defer func() { if r := recover(); r != nil { err = fmt.Errorf("panic: %v\n%s", r, debug.Stack()) @@ -810,8 +895,6 @@ func (e *Enforcer) enforce(matcher string, explains *[]string, rvals ...interfac } } - var logExplains [][]string - if explains != nil { if len(*explains) > 0 { logExplains = append(logExplains, *explains) @@ -1012,3 +1095,11 @@ func generateEvalFunction(functions map[string]govaluate.ExpressionFunction, par return expr.Eval(parameters) } } + +// toString converts an interface{} to string for logging +func toString(v interface{}) string { + if s, ok := v.(string); ok { + return s + } + return "" +} diff --git a/log/default_event_logger.go b/log/default_event_logger.go new file mode 100644 index 000000000..dd3453efd --- /dev/null +++ b/log/default_event_logger.go @@ -0,0 +1,53 @@ +// Copyright 2024 The casbin Authors. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package log + +// DefaultEventLogger is a no-op event logger implementation +type DefaultEventLogger struct { + enabled bool + subscribe []EventType +} + +// NewDefaultEventLogger creates a new DefaultEventLogger +func NewDefaultEventLogger() *DefaultEventLogger { + return &DefaultEventLogger{ + enabled: false, + subscribe: nil, // nil means subscribe to all events + } +} + +func (l *DefaultEventLogger) Enable(enabled bool) { + l.enabled = enabled +} + +func (l *DefaultEventLogger) IsEnabled() bool { + return l.enabled +} + +func (l *DefaultEventLogger) Subscribe() []EventType { + return l.subscribe +} + +func (l *DefaultEventLogger) SetSubscribe(events []EventType) { + l.subscribe = events +} + +func (l *DefaultEventLogger) OnBeforeEvent(entry *LogEntry) *Handle { + return NewHandle() +} + +func (l *DefaultEventLogger) OnAfterEvent(handle *Handle, entry *LogEntry) { + // Default implementation does nothing +} diff --git a/log/event_logger.go b/log/event_logger.go new file mode 100644 index 000000000..619b022b8 --- /dev/null +++ b/log/event_logger.go @@ -0,0 +1,111 @@ +// Copyright 2024 The casbin Authors. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package log + +import ( + "time" +) + +// ==================== Event Types ==================== + +// EventType represents the type of event being logged +type EventType string + +const ( + EventEnforce EventType = "enforce" + EventPolicyAdd EventType = "policy.add" + EventPolicyRemove EventType = "policy.remove" + EventPolicyUpdate EventType = "policy.update" + EventPolicyLoad EventType = "policy.load" + EventPolicySave EventType = "policy.save" + EventModelLoad EventType = "model.load" + EventRoleAdd EventType = "role.add" + EventRoleRemove EventType = "role.remove" +) + +// ==================== Handle ==================== + +// Handle is passed from OnBeforeEvent to OnAfterEvent +// Logger implementations can store custom data in the Store field +type Handle struct { + // StartTime records when the event started + StartTime time.Time + + // Store allows logger implementations to attach custom data + // e.g., OpenTelemetry can store Span, context, etc. + Store map[string]interface{} +} + +// NewHandle creates a new Handle with initialized fields +func NewHandle() *Handle { + return &Handle{ + StartTime: time.Now(), + Store: make(map[string]interface{}), + } +} + +// ==================== Log Entry ==================== + +// LogEntry contains all information about an event +type LogEntry struct { + // Event info + Type EventType + Timestamp time.Time + Duration time.Duration // Filled in OnAfterEvent + + // Enforce related + Request []interface{} + Subject string + Object string + Action string + Domain string + Allowed bool + Matched [][]string + + // Policy/Role related + Operation string + Rules [][]string + RuleCount int + + // Error info + Error error + + // Custom attributes (can store context.Context, trace IDs, etc.) + Attributes map[string]interface{} +} + +// ==================== Event Logger Interface ==================== + +// EventLogger is the unified interface for logging, tracing, and metrics +type EventLogger interface { + // Enable turns the logger on or off + Enable(enabled bool) + + // IsEnabled returns whether the logger is enabled + IsEnabled() bool + + // Subscribe returns the list of event types this logger is interested in + // Return nil or empty slice to subscribe to all events + // Return specific event types to filter events + Subscribe() []EventType + + // OnBeforeEvent is called before an event occurs + // Returns a Handle that will be passed to OnAfterEvent + OnBeforeEvent(entry *LogEntry) *Handle + + // OnAfterEvent is called after an event completes + // The Handle from OnBeforeEvent is passed back along with the updated entry + OnAfterEvent(handle *Handle, entry *LogEntry) +} From 01b4448f6336572791df99d0346833dc4bdbc4b7 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sat, 13 Dec 2025 13:54:50 +0000 Subject: [PATCH 3/8] Instrument policy operations and add GetPolicyCount method Co-authored-by: hsluoyz <3787410+hsluoyz@users.noreply.github.com> --- enforcer.go | 72 ++++++++++++++++++++- internal_api.go | 162 +++++++++++++++++++++++++++++++++++++++++----- management_api.go | 11 ++++ 3 files changed, 228 insertions(+), 17 deletions(-) diff --git a/enforcer.go b/enforcer.go index b83a89da6..6b4ce15a9 100644 --- a/enforcer.go +++ b/enforcer.go @@ -371,14 +371,46 @@ func (e *Enforcer) ClearPolicy() { // LoadPolicy reloads the policy from file/database. func (e *Enforcer) LoadPolicy() error { + // Event logging setup + var entry *log.LogEntry + var handle *log.Handle + shouldLog := e.shouldLog(log.EventPolicyLoad) + + if shouldLog { + entry = &log.LogEntry{ + Type: log.EventPolicyLoad, + Timestamp: time.Now(), + Operation: "load", + Attributes: make(map[string]interface{}), + } + handle = e.eventLogger.OnBeforeEvent(entry) + } + newModel, err := e.loadPolicyFromAdapter(e.model) if err != nil { + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + entry.Error = err + e.eventLogger.OnAfterEvent(handle, entry) + } return err } err = e.applyModifiedModel(newModel) if err != nil { + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + entry.Error = err + e.eventLogger.OnAfterEvent(handle, entry) + } return err } + + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + entry.RuleCount = e.GetPolicyCount() + e.eventLogger.OnAfterEvent(handle, entry) + } + return nil } @@ -522,10 +554,37 @@ func (e *Enforcer) IsFiltered() bool { // SavePolicy saves the current policy (usually after changed with Casbin API) back to file/database. func (e *Enforcer) SavePolicy() error { + // Event logging setup + var entry *log.LogEntry + var handle *log.Handle + shouldLog := e.shouldLog(log.EventPolicySave) + + if shouldLog { + entry = &log.LogEntry{ + Type: log.EventPolicySave, + Timestamp: time.Now(), + Operation: "save", + RuleCount: e.GetPolicyCount(), + Attributes: make(map[string]interface{}), + } + handle = e.eventLogger.OnBeforeEvent(entry) + } + if e.IsFiltered() { - return errors.New("cannot save a filtered policy") + err := errors.New("cannot save a filtered policy") + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + entry.Error = err + e.eventLogger.OnAfterEvent(handle, entry) + } + return err } if err := e.adapter.SavePolicy(e.model); err != nil { + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + entry.Error = err + e.eventLogger.OnAfterEvent(handle, entry) + } return err } if e.watcher != nil { @@ -535,8 +594,19 @@ func (e *Enforcer) SavePolicy() error { } else { err = e.watcher.Update() } + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + entry.Error = err + e.eventLogger.OnAfterEvent(handle, entry) + } return err } + + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + e.eventLogger.OnAfterEvent(handle, entry) + } + return nil } diff --git a/internal_api.go b/internal_api.go index 1a573e090..85c821e58 100644 --- a/internal_api.go +++ b/internal_api.go @@ -16,8 +16,10 @@ package casbin import ( "fmt" + "time" Err "github.com/casbin/casbin/v3/errors" + "github.com/casbin/casbin/v3/log" "github.com/casbin/casbin/v3/model" "github.com/casbin/casbin/v3/persist" ) @@ -329,19 +331,51 @@ func (e *Enforcer) updateFilteredPoliciesWithoutNotify(sec string, ptype string, // addPolicy adds a rule to the current policy. func (e *Enforcer) addPolicy(sec string, ptype string, rule []string) (bool, error) { + // Event logging setup + var entry *log.LogEntry + var handle *log.Handle + shouldLog := e.shouldLog(log.EventPolicyAdd) + + if shouldLog { + entry = &log.LogEntry{ + Type: log.EventPolicyAdd, + Timestamp: time.Now(), + Operation: "add", + Rules: [][]string{rule}, + RuleCount: 1, + Attributes: make(map[string]interface{}), + } + handle = e.eventLogger.OnBeforeEvent(entry) + } + ok, err := e.addPolicyWithoutNotify(sec, ptype, rule) if !ok || err != nil { + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + entry.Error = err + e.eventLogger.OnAfterEvent(handle, entry) + } return ok, err } if e.shouldNotify() { - var err error + var notifyErr error if watcher, ok := e.watcher.(persist.WatcherEx); ok { - err = watcher.UpdateForAddPolicy(sec, ptype, rule...) + notifyErr = watcher.UpdateForAddPolicy(sec, ptype, rule...) } else { - err = e.watcher.Update() + notifyErr = e.watcher.Update() } - return true, err + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + entry.Error = notifyErr + e.eventLogger.OnAfterEvent(handle, entry) + } + return true, notifyErr + } + + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + e.eventLogger.OnAfterEvent(handle, entry) } return true, nil @@ -351,19 +385,51 @@ func (e *Enforcer) addPolicy(sec string, ptype string, rule []string) (bool, err // If autoRemoveRepeat == true, existing rules are automatically filtered // Otherwise, false is returned directly. func (e *Enforcer) addPolicies(sec string, ptype string, rules [][]string, autoRemoveRepeat bool) (bool, error) { + // Event logging setup + var entry *log.LogEntry + var handle *log.Handle + shouldLog := e.shouldLog(log.EventPolicyAdd) + + if shouldLog { + entry = &log.LogEntry{ + Type: log.EventPolicyAdd, + Timestamp: time.Now(), + Operation: "add", + Rules: rules, + RuleCount: len(rules), + Attributes: make(map[string]interface{}), + } + handle = e.eventLogger.OnBeforeEvent(entry) + } + ok, err := e.addPoliciesWithoutNotify(sec, ptype, rules, autoRemoveRepeat) if !ok || err != nil { + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + entry.Error = err + e.eventLogger.OnAfterEvent(handle, entry) + } return ok, err } if e.shouldNotify() { - var err error + var notifyErr error if watcher, ok := e.watcher.(persist.WatcherEx); ok { - err = watcher.UpdateForAddPolicies(sec, ptype, rules...) + notifyErr = watcher.UpdateForAddPolicies(sec, ptype, rules...) } else { - err = e.watcher.Update() + notifyErr = e.watcher.Update() } - return true, err + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + entry.Error = notifyErr + e.eventLogger.OnAfterEvent(handle, entry) + } + return true, notifyErr + } + + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + e.eventLogger.OnAfterEvent(handle, entry) } return true, nil @@ -371,38 +437,102 @@ func (e *Enforcer) addPolicies(sec string, ptype string, rules [][]string, autoR // removePolicy removes a rule from the current policy. func (e *Enforcer) removePolicy(sec string, ptype string, rule []string) (bool, error) { + // Event logging setup + var entry *log.LogEntry + var handle *log.Handle + shouldLog := e.shouldLog(log.EventPolicyRemove) + + if shouldLog { + entry = &log.LogEntry{ + Type: log.EventPolicyRemove, + Timestamp: time.Now(), + Operation: "remove", + Rules: [][]string{rule}, + RuleCount: 1, + Attributes: make(map[string]interface{}), + } + handle = e.eventLogger.OnBeforeEvent(entry) + } + ok, err := e.removePolicyWithoutNotify(sec, ptype, rule) if !ok || err != nil { + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + entry.Error = err + e.eventLogger.OnAfterEvent(handle, entry) + } return ok, err } if e.shouldNotify() { - var err error + var notifyErr error if watcher, ok := e.watcher.(persist.WatcherEx); ok { - err = watcher.UpdateForRemovePolicy(sec, ptype, rule...) + notifyErr = watcher.UpdateForRemovePolicy(sec, ptype, rule...) } else { - err = e.watcher.Update() + notifyErr = e.watcher.Update() } - return true, err + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + entry.Error = notifyErr + e.eventLogger.OnAfterEvent(handle, entry) + } + return true, notifyErr + } + + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + e.eventLogger.OnAfterEvent(handle, entry) } return true, nil } func (e *Enforcer) updatePolicy(sec string, ptype string, oldRule []string, newRule []string) (bool, error) { + // Event logging setup + var entry *log.LogEntry + var handle *log.Handle + shouldLog := e.shouldLog(log.EventPolicyUpdate) + + if shouldLog { + entry = &log.LogEntry{ + Type: log.EventPolicyUpdate, + Timestamp: time.Now(), + Operation: "update", + Rules: [][]string{oldRule, newRule}, + RuleCount: 1, + Attributes: make(map[string]interface{}), + } + handle = e.eventLogger.OnBeforeEvent(entry) + } + ok, err := e.updatePolicyWithoutNotify(sec, ptype, oldRule, newRule) if !ok || err != nil { + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + entry.Error = err + e.eventLogger.OnAfterEvent(handle, entry) + } return ok, err } if e.shouldNotify() { - var err error + var notifyErr error if watcher, ok := e.watcher.(persist.UpdatableWatcher); ok { - err = watcher.UpdateForUpdatePolicy(sec, ptype, oldRule, newRule) + notifyErr = watcher.UpdateForUpdatePolicy(sec, ptype, oldRule, newRule) } else { - err = e.watcher.Update() + notifyErr = e.watcher.Update() } - return true, err + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + entry.Error = notifyErr + e.eventLogger.OnAfterEvent(handle, entry) + } + return true, notifyErr + } + + if shouldLog { + entry.Duration = time.Since(entry.Timestamp) + e.eventLogger.OnAfterEvent(handle, entry) } return true, nil diff --git a/management_api.go b/management_api.go index c6a55418a..3d2b5b333 100644 --- a/management_api.go +++ b/management_api.go @@ -81,6 +81,17 @@ func (e *Enforcer) GetPolicy() ([][]string, error) { return e.GetNamedPolicy("p") } +// GetPolicyCount gets the count of all authorization rules in the policy. +func (e *Enforcer) GetPolicyCount() int { + count := 0 + if e.model != nil && e.model["p"] != nil { + for _, ast := range e.model["p"] { + count += len(ast.Policy) + } + } + return count +} + // GetFilteredPolicy gets all the authorization rules in the policy, field filters can be specified. func (e *Enforcer) GetFilteredPolicy(fieldIndex int, fieldValues ...string) ([][]string, error) { return e.GetFilteredNamedPolicy("p", fieldIndex, fieldValues...) From 6bf44eec3e44570031ad7ca8de3234095f561b07 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sat, 13 Dec 2025 13:57:15 +0000 Subject: [PATCH 4/8] Add comprehensive tests for event logger functionality Co-authored-by: hsluoyz <3787410+hsluoyz@users.noreply.github.com> --- event_logger_test.go | 275 +++++++++++++++++++++++++++++++++++++++ log/event_logger_test.go | 201 ++++++++++++++++++++++++++++ 2 files changed, 476 insertions(+) create mode 100644 event_logger_test.go create mode 100644 log/event_logger_test.go diff --git a/event_logger_test.go b/event_logger_test.go new file mode 100644 index 000000000..f978ec47c --- /dev/null +++ b/event_logger_test.go @@ -0,0 +1,275 @@ +// Copyright 2024 The casbin Authors. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package casbin + +import ( + "testing" + + "github.com/casbin/casbin/v3/log" +) + +// TestEventLogger is a test logger implementation that captures events +type TestEventLogger struct { + enabled bool + subscribe []log.EventType + events []*log.LogEntry +} + +func NewTestEventLogger(subscribe ...log.EventType) *TestEventLogger { + return &TestEventLogger{ + enabled: true, + subscribe: subscribe, + events: make([]*log.LogEntry, 0), + } +} + +func (l *TestEventLogger) Enable(enabled bool) { + l.enabled = enabled +} + +func (l *TestEventLogger) IsEnabled() bool { + return l.enabled +} + +func (l *TestEventLogger) Subscribe() []log.EventType { + return l.subscribe +} + +func (l *TestEventLogger) OnBeforeEvent(entry *log.LogEntry) *log.Handle { + return log.NewHandle() +} + +func (l *TestEventLogger) OnAfterEvent(handle *log.Handle, entry *log.LogEntry) { + // Store a copy of the entry + l.events = append(l.events, entry) +} + +func (l *TestEventLogger) GetEvents() []*log.LogEntry { + return l.events +} + +func (l *TestEventLogger) Clear() { + l.events = make([]*log.LogEntry, 0) +} + +func TestEnforcerWithEventLogger(t *testing.T) { + e, _ := NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv") + + logger := NewTestEventLogger(log.EventEnforce) + e.SetEventLogger(logger) + + // Test enforce + result, _ := e.Enforce("alice", "data1", "read") + if !result { + t.Error("alice should be able to read data1") + } + + events := logger.GetEvents() + if len(events) != 1 { + t.Errorf("Expected 1 event, got %d", len(events)) + } + + event := events[0] + if event.Type != log.EventEnforce { + t.Errorf("Expected EventEnforce, got %v", event.Type) + } + + if event.Subject != "alice" { + t.Errorf("Expected subject 'alice', got %s", event.Subject) + } + + if event.Object != "data1" { + t.Errorf("Expected object 'data1', got %s", event.Object) + } + + if event.Action != "read" { + t.Errorf("Expected action 'read', got %s", event.Action) + } + + if !event.Allowed { + t.Error("Event should show allowed=true") + } + + if event.Error != nil { + t.Errorf("Event should not have error, got: %v", event.Error) + } + + if event.Duration <= 0 { + t.Error("Event duration should be > 0") + } +} + +func TestEnforcerPolicyAddEvent(t *testing.T) { + e, _ := NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv") + + logger := NewTestEventLogger(log.EventPolicyAdd) + e.SetEventLogger(logger) + + // Test add policy + ok, _ := e.AddPolicy("eve", "data3", "read") + if !ok { + t.Error("AddPolicy should succeed") + } + + events := logger.GetEvents() + if len(events) != 1 { + t.Errorf("Expected 1 event, got %d", len(events)) + } + + event := events[0] + if event.Type != log.EventPolicyAdd { + t.Errorf("Expected EventPolicyAdd, got %v", event.Type) + } + + if event.Operation != "add" { + t.Errorf("Expected operation 'add', got %s", event.Operation) + } + + if event.RuleCount != 1 { + t.Errorf("Expected rule count 1, got %d", event.RuleCount) + } + + if len(event.Rules) != 1 { + t.Errorf("Expected 1 rule, got %d", len(event.Rules)) + } +} + +func TestEnforcerPolicyRemoveEvent(t *testing.T) { + e, _ := NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv") + + logger := NewTestEventLogger(log.EventPolicyRemove) + e.SetEventLogger(logger) + + // Test remove policy + ok, _ := e.RemovePolicy("alice", "data1", "read") + if !ok { + t.Error("RemovePolicy should succeed") + } + + events := logger.GetEvents() + if len(events) != 1 { + t.Errorf("Expected 1 event, got %d", len(events)) + } + + event := events[0] + if event.Type != log.EventPolicyRemove { + t.Errorf("Expected EventPolicyRemove, got %v", event.Type) + } + + if event.Operation != "remove" { + t.Errorf("Expected operation 'remove', got %s", event.Operation) + } +} + +func TestEnforcerLoadPolicyEvent(t *testing.T) { + e, _ := NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv") + + logger := NewTestEventLogger(log.EventPolicyLoad) + e.SetEventLogger(logger) + + // Test load policy + err := e.LoadPolicy() + if err != nil { + t.Errorf("LoadPolicy should succeed, got error: %v", err) + } + + events := logger.GetEvents() + if len(events) != 1 { + t.Errorf("Expected 1 event, got %d", len(events)) + } + + event := events[0] + if event.Type != log.EventPolicyLoad { + t.Errorf("Expected EventPolicyLoad, got %v", event.Type) + } + + if event.Operation != "load" { + t.Errorf("Expected operation 'load', got %s", event.Operation) + } + + if event.RuleCount == 0 { + t.Error("Expected rule count > 0") + } +} + +func TestEventLoggerSubscription(t *testing.T) { + e, _ := NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv") + + // Subscribe only to enforce events + logger := NewTestEventLogger(log.EventEnforce) + e.SetEventLogger(logger) + + // Enforce should be logged + e.Enforce("alice", "data1", "read") + + // AddPolicy should NOT be logged + e.AddPolicy("eve", "data3", "read") + + events := logger.GetEvents() + if len(events) != 1 { + t.Errorf("Expected 1 event (only enforce), got %d", len(events)) + } + + if events[0].Type != log.EventEnforce { + t.Errorf("Expected EventEnforce, got %v", events[0].Type) + } +} + +func TestEventLoggerSubscribeToAll(t *testing.T) { + e, _ := NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv") + + // Subscribe to all events (pass no arguments) + logger := NewTestEventLogger() + e.SetEventLogger(logger) + + // Multiple operations + e.Enforce("alice", "data1", "read") + e.AddPolicy("eve", "data3", "read") + e.RemovePolicy("eve", "data3", "read") + + events := logger.GetEvents() + if len(events) != 3 { + t.Errorf("Expected 3 events, got %d", len(events)) + } + + // Verify event types + expectedTypes := []log.EventType{ + log.EventEnforce, + log.EventPolicyAdd, + log.EventPolicyRemove, + } + + for i, expected := range expectedTypes { + if events[i].Type != expected { + t.Errorf("Event %d: expected %v, got %v", i, expected, events[i].Type) + } + } +} + +func TestEventLoggerDisabled(t *testing.T) { + e, _ := NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv") + + logger := NewTestEventLogger(log.EventEnforce) + logger.Enable(false) + e.SetEventLogger(logger) + + // This should not be logged + e.Enforce("alice", "data1", "read") + + events := logger.GetEvents() + if len(events) != 0 { + t.Errorf("Expected 0 events when logger is disabled, got %d", len(events)) + } +} diff --git a/log/event_logger_test.go b/log/event_logger_test.go new file mode 100644 index 000000000..d99aaac9e --- /dev/null +++ b/log/event_logger_test.go @@ -0,0 +1,201 @@ +// Copyright 2024 The casbin Authors. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package log + +import ( + "testing" + "time" +) + +// TestEventLogger is a test logger implementation that captures events +type TestEventLogger struct { + enabled bool + subscribe []EventType + events []*LogEntry +} + +func NewTestEventLogger(subscribe ...EventType) *TestEventLogger { + return &TestEventLogger{ + enabled: true, + subscribe: subscribe, + events: make([]*LogEntry, 0), + } +} + +func (l *TestEventLogger) Enable(enabled bool) { + l.enabled = enabled +} + +func (l *TestEventLogger) IsEnabled() bool { + return l.enabled +} + +func (l *TestEventLogger) Subscribe() []EventType { + return l.subscribe +} + +func (l *TestEventLogger) OnBeforeEvent(entry *LogEntry) *Handle { + return NewHandle() +} + +func (l *TestEventLogger) OnAfterEvent(handle *Handle, entry *LogEntry) { + // Store a copy of the entry + l.events = append(l.events, entry) +} + +func (l *TestEventLogger) GetEvents() []*LogEntry { + return l.events +} + +func (l *TestEventLogger) Clear() { + l.events = make([]*LogEntry, 0) +} + +func TestNewHandle(t *testing.T) { + handle := NewHandle() + if handle == nil { + t.Error("NewHandle should not return nil") + } + if handle.Store == nil { + t.Error("Handle.Store should be initialized") + } + if handle.StartTime.IsZero() { + t.Error("Handle.StartTime should be set") + } +} + +func TestDefaultEventLogger(t *testing.T) { + logger := NewDefaultEventLogger() + + if logger.IsEnabled() { + t.Error("DefaultEventLogger should be disabled by default") + } + + logger.Enable(true) + if !logger.IsEnabled() { + t.Error("DefaultEventLogger should be enabled after Enable(true)") + } + + if logger.Subscribe() != nil { + t.Error("DefaultEventLogger should subscribe to all events by default (nil)") + } + + // Test that it doesn't panic when called + entry := &LogEntry{ + Type: EventEnforce, + Timestamp: time.Now(), + } + handle := logger.OnBeforeEvent(entry) + if handle == nil { + t.Error("OnBeforeEvent should return a handle") + } + + logger.OnAfterEvent(handle, entry) +} + +func TestTestEventLogger(t *testing.T) { + logger := NewTestEventLogger(EventEnforce, EventPolicyAdd) + + if !logger.IsEnabled() { + t.Error("TestEventLogger should be enabled by default") + } + + subscribe := logger.Subscribe() + if len(subscribe) != 2 { + t.Errorf("Expected 2 subscriptions, got %d", len(subscribe)) + } + + // Test event capture + entry := &LogEntry{ + Type: EventEnforce, + Timestamp: time.Now(), + Subject: "alice", + Object: "data1", + Action: "read", + Allowed: true, + } + + handle := logger.OnBeforeEvent(entry) + entry.Duration = time.Since(handle.StartTime) + logger.OnAfterEvent(handle, entry) + + events := logger.GetEvents() + if len(events) != 1 { + t.Errorf("Expected 1 event, got %d", len(events)) + } + + if events[0].Type != EventEnforce { + t.Errorf("Expected EventEnforce, got %v", events[0].Type) + } + + if events[0].Subject != "alice" { + t.Errorf("Expected subject 'alice', got %s", events[0].Subject) + } +} + +func TestEventTypes(t *testing.T) { + types := []EventType{ + EventEnforce, + EventPolicyAdd, + EventPolicyRemove, + EventPolicyUpdate, + EventPolicyLoad, + EventPolicySave, + EventModelLoad, + EventRoleAdd, + EventRoleRemove, + } + + for _, eventType := range types { + if string(eventType) == "" { + t.Errorf("Event type should not be empty: %v", eventType) + } + } +} + +func TestLogEntry(t *testing.T) { + entry := &LogEntry{ + Type: EventEnforce, + Timestamp: time.Now(), + Duration: time.Millisecond * 10, + Request: []interface{}{"alice", "data1", "read"}, + Subject: "alice", + Object: "data1", + Action: "read", + Allowed: true, + Matched: [][]string{{"alice", "data1", "read"}}, + Operation: "", + Rules: nil, + RuleCount: 0, + Error: nil, + Attributes: make(map[string]interface{}), + } + + if entry.Type != EventEnforce { + t.Error("Entry type mismatch") + } + + if entry.Subject != "alice" { + t.Error("Entry subject mismatch") + } + + if !entry.Allowed { + t.Error("Entry should be allowed") + } + + if entry.Duration < time.Millisecond { + t.Error("Entry duration too short") + } +} From 25e8e1d1219ec27382844ffa434b4c184145c476 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sat, 13 Dec 2025 13:59:52 +0000 Subject: [PATCH 5/8] Address code review feedback: fix duration calculations and improve toString Co-authored-by: hsluoyz <3787410+hsluoyz@users.noreply.github.com> --- enforcer.go | 20 ++++++++++---------- internal_api.go | 24 ++++++++++++------------ log/default_event_logger.go | 4 ---- 3 files changed, 22 insertions(+), 26 deletions(-) diff --git a/enforcer.go b/enforcer.go index 6b4ce15a9..ea6369a52 100644 --- a/enforcer.go +++ b/enforcer.go @@ -224,8 +224,8 @@ func (e *Enforcer) updateSubscribeCache() { } events := e.eventLogger.Subscribe() + // Both nil and empty slice mean subscribe to all events if len(events) == 0 { - // Empty means subscribe to all e.subscribeCache = nil return } @@ -389,7 +389,7 @@ func (e *Enforcer) LoadPolicy() error { newModel, err := e.loadPolicyFromAdapter(e.model) if err != nil { if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.Error = err e.eventLogger.OnAfterEvent(handle, entry) } @@ -398,7 +398,7 @@ func (e *Enforcer) LoadPolicy() error { err = e.applyModifiedModel(newModel) if err != nil { if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.Error = err e.eventLogger.OnAfterEvent(handle, entry) } @@ -406,7 +406,7 @@ func (e *Enforcer) LoadPolicy() error { } if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.RuleCount = e.GetPolicyCount() e.eventLogger.OnAfterEvent(handle, entry) } @@ -573,7 +573,7 @@ func (e *Enforcer) SavePolicy() error { if e.IsFiltered() { err := errors.New("cannot save a filtered policy") if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.Error = err e.eventLogger.OnAfterEvent(handle, entry) } @@ -581,7 +581,7 @@ func (e *Enforcer) SavePolicy() error { } if err := e.adapter.SavePolicy(e.model); err != nil { if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.Error = err e.eventLogger.OnAfterEvent(handle, entry) } @@ -595,7 +595,7 @@ func (e *Enforcer) SavePolicy() error { err = e.watcher.Update() } if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.Error = err e.eventLogger.OnAfterEvent(handle, entry) } @@ -603,7 +603,7 @@ func (e *Enforcer) SavePolicy() error { } if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) e.eventLogger.OnAfterEvent(handle, entry) } @@ -757,7 +757,7 @@ func (e *Enforcer) enforce(matcher string, explains *[]string, rvals ...interfac defer func() { if shouldLog && entry != nil && handle != nil { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.Allowed = ok entry.Matched = logExplains entry.Error = err @@ -1171,5 +1171,5 @@ func toString(v interface{}) string { if s, ok := v.(string); ok { return s } - return "" + return fmt.Sprintf("%v", v) } diff --git a/internal_api.go b/internal_api.go index 85c821e58..3d4280ada 100644 --- a/internal_api.go +++ b/internal_api.go @@ -351,7 +351,7 @@ func (e *Enforcer) addPolicy(sec string, ptype string, rule []string) (bool, err ok, err := e.addPolicyWithoutNotify(sec, ptype, rule) if !ok || err != nil { if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.Error = err e.eventLogger.OnAfterEvent(handle, entry) } @@ -366,7 +366,7 @@ func (e *Enforcer) addPolicy(sec string, ptype string, rule []string) (bool, err notifyErr = e.watcher.Update() } if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.Error = notifyErr e.eventLogger.OnAfterEvent(handle, entry) } @@ -374,7 +374,7 @@ func (e *Enforcer) addPolicy(sec string, ptype string, rule []string) (bool, err } if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) e.eventLogger.OnAfterEvent(handle, entry) } @@ -405,7 +405,7 @@ func (e *Enforcer) addPolicies(sec string, ptype string, rules [][]string, autoR ok, err := e.addPoliciesWithoutNotify(sec, ptype, rules, autoRemoveRepeat) if !ok || err != nil { if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.Error = err e.eventLogger.OnAfterEvent(handle, entry) } @@ -420,7 +420,7 @@ func (e *Enforcer) addPolicies(sec string, ptype string, rules [][]string, autoR notifyErr = e.watcher.Update() } if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.Error = notifyErr e.eventLogger.OnAfterEvent(handle, entry) } @@ -428,7 +428,7 @@ func (e *Enforcer) addPolicies(sec string, ptype string, rules [][]string, autoR } if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) e.eventLogger.OnAfterEvent(handle, entry) } @@ -457,7 +457,7 @@ func (e *Enforcer) removePolicy(sec string, ptype string, rule []string) (bool, ok, err := e.removePolicyWithoutNotify(sec, ptype, rule) if !ok || err != nil { if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.Error = err e.eventLogger.OnAfterEvent(handle, entry) } @@ -472,7 +472,7 @@ func (e *Enforcer) removePolicy(sec string, ptype string, rule []string) (bool, notifyErr = e.watcher.Update() } if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.Error = notifyErr e.eventLogger.OnAfterEvent(handle, entry) } @@ -480,7 +480,7 @@ func (e *Enforcer) removePolicy(sec string, ptype string, rule []string) (bool, } if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) e.eventLogger.OnAfterEvent(handle, entry) } @@ -508,7 +508,7 @@ func (e *Enforcer) updatePolicy(sec string, ptype string, oldRule []string, newR ok, err := e.updatePolicyWithoutNotify(sec, ptype, oldRule, newRule) if !ok || err != nil { if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.Error = err e.eventLogger.OnAfterEvent(handle, entry) } @@ -523,7 +523,7 @@ func (e *Enforcer) updatePolicy(sec string, ptype string, oldRule []string, newR notifyErr = e.watcher.Update() } if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) entry.Error = notifyErr e.eventLogger.OnAfterEvent(handle, entry) } @@ -531,7 +531,7 @@ func (e *Enforcer) updatePolicy(sec string, ptype string, oldRule []string, newR } if shouldLog { - entry.Duration = time.Since(entry.Timestamp) + entry.Duration = time.Since(handle.StartTime) e.eventLogger.OnAfterEvent(handle, entry) } diff --git a/log/default_event_logger.go b/log/default_event_logger.go index dd3453efd..b400e4da1 100644 --- a/log/default_event_logger.go +++ b/log/default_event_logger.go @@ -40,10 +40,6 @@ func (l *DefaultEventLogger) Subscribe() []EventType { return l.subscribe } -func (l *DefaultEventLogger) SetSubscribe(events []EventType) { - l.subscribe = events -} - func (l *DefaultEventLogger) OnBeforeEvent(entry *LogEntry) *Handle { return NewHandle() } From 2c2932074f83f461ee0ed72be361e62ad7fce406 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sat, 13 Dec 2025 14:01:42 +0000 Subject: [PATCH 6/8] Fix formatting: remove extra blank line Co-authored-by: hsluoyz <3787410+hsluoyz@users.noreply.github.com> --- enforcer.go | 1 - 1 file changed, 1 deletion(-) diff --git a/enforcer.go b/enforcer.go index ea6369a52..9313c0729 100644 --- a/enforcer.go +++ b/enforcer.go @@ -249,7 +249,6 @@ func (e *Enforcer) shouldLog(eventType log.EventType) bool { return e.subscribeCache[eventType] } - func (e *Enforcer) initialize() { e.rmMap = map[string]rbac.RoleManager{} e.condRmMap = map[string]rbac.ConditionalRoleManager{} From 8d1a860d91af83a317de275a44f5b3711770816a Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sun, 21 Dec 2025 07:37:59 +0000 Subject: [PATCH 7/8] Refactor logger interface: remove 'event' prefix, replace old logger with new event-based logger - Renamed EventLogger to Logger and DefaultEventLogger to DefaultLogger - Renamed event_logger.go to logger.go and default_event_logger.go to default_logger.go - Removed old Logger interface methods (LogModel, LogPolicy, LogRole, LogError) - Updated enforcer to use single logger field instead of separate eventLogger - Made model and role manager SetLogger/GetLogger methods no-ops for backward compatibility - Removed log_util.go and log_util_test.go (no longer needed) - Added helper functions logEventStart() and logEventEnd() for cleaner hook code - All comments now end with periods per godot linting rule - Updated all references from eventLogger to logger throughout codebase - Renamed event_logger_test.go to logger_integration_test.go and updated all references Co-authored-by: hsluoyz <3787410+hsluoyz@users.noreply.github.com> --- enforcer.go | 84 +++++++------ enforcer_cached.go | 2 +- internal_api.go | 32 ++--- log/default_event_logger.go | 49 -------- log/default_logger.go | 100 ++++------------ log/event_logger.go | 111 ------------------ log/log_util.go | 52 -------- log/log_util_test.go | 56 --------- log/logger.go | 106 ++++++++++++++--- log/{event_logger_test.go => logger_test.go} | 86 ++++++++------ ...gger_test.go => logger_integration_test.go | 58 ++++----- model/model.go | 37 ++---- model/policy.go | 30 +---- rbac/default-role-manager/role_manager.go | 24 ++-- 14 files changed, 282 insertions(+), 545 deletions(-) delete mode 100644 log/default_event_logger.go delete mode 100644 log/event_logger.go delete mode 100644 log/log_util.go delete mode 100644 log/log_util_test.go rename log/{event_logger_test.go => logger_test.go} (70%) rename event_logger_test.go => logger_integration_test.go (80%) diff --git a/enforcer.go b/enforcer.go index 9313c0729..e40d114fc 100644 --- a/enforcer.go +++ b/enforcer.go @@ -56,7 +56,6 @@ type Enforcer struct { acceptJsonRequest bool logger log.Logger - eventLogger log.EventLogger subscribeCache map[log.EventType]bool } @@ -83,7 +82,7 @@ func (e EnforceContext) GetCacheKey() string { // a := mysqladapter.NewDBAdapter("mysql", "mysql_username:mysql_password@tcp(127.0.0.1:3306)/") // e := casbin.NewEnforcer("path/to/basic_model.conf", a) func NewEnforcer(params ...interface{}) (*Enforcer, error) { - e := &Enforcer{logger: &log.DefaultLogger{}} + e := &Enforcer{logger: log.NewDefaultLogger()} parsedParamLen := 0 paramLen := len(params) @@ -197,34 +196,22 @@ func (e *Enforcer) InitWithModelAndAdapter(m model.Model, adapter persist.Adapte return nil } -// SetLogger changes the current enforcer's logger. +// SetLogger sets the logger for the enforcer. func (e *Enforcer) SetLogger(logger log.Logger) { e.logger = logger - e.model.SetLogger(e.logger) - for k := range e.rmMap { - e.rmMap[k].SetLogger(e.logger) - } - for k := range e.condRmMap { - e.condRmMap[k].SetLogger(e.logger) - } -} - -// SetEventLogger sets the event logger for the enforcer. -func (e *Enforcer) SetEventLogger(logger log.EventLogger) { - e.eventLogger = logger e.updateSubscribeCache() } -// updateSubscribeCache updates the subscription cache for quick event type lookup +// updateSubscribeCache updates the subscription cache for quick event type lookup. func (e *Enforcer) updateSubscribeCache() { e.subscribeCache = make(map[log.EventType]bool) - if e.eventLogger == nil { + if e.logger == nil { return } - events := e.eventLogger.Subscribe() - // Both nil and empty slice mean subscribe to all events + events := e.logger.Subscribe() + // Both nil and empty slice mean subscribe to all events. if len(events) == 0 { e.subscribeCache = nil return @@ -235,13 +222,13 @@ func (e *Enforcer) updateSubscribeCache() { } } -// shouldLog checks if we should log this event type +// shouldLog checks if we should log this event type. func (e *Enforcer) shouldLog(eventType log.EventType) bool { - if e.eventLogger == nil || !e.eventLogger.IsEnabled() { + if e.logger == nil || !e.logger.IsEnabled() { return false } - // nil cache means subscribe to all events + // nil cache means subscribe to all events. if e.subscribeCache == nil { return true } @@ -382,7 +369,7 @@ func (e *Enforcer) LoadPolicy() error { Operation: "load", Attributes: make(map[string]interface{}), } - handle = e.eventLogger.OnBeforeEvent(entry) + handle = e.logger.OnBeforeEvent(entry) } newModel, err := e.loadPolicyFromAdapter(e.model) @@ -390,7 +377,7 @@ func (e *Enforcer) LoadPolicy() error { if shouldLog { entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return err } @@ -399,7 +386,7 @@ func (e *Enforcer) LoadPolicy() error { if shouldLog { entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return err } @@ -407,7 +394,7 @@ func (e *Enforcer) LoadPolicy() error { if shouldLog { entry.Duration = time.Since(handle.StartTime) entry.RuleCount = e.GetPolicyCount() - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return nil @@ -566,7 +553,7 @@ func (e *Enforcer) SavePolicy() error { RuleCount: e.GetPolicyCount(), Attributes: make(map[string]interface{}), } - handle = e.eventLogger.OnBeforeEvent(entry) + handle = e.logger.OnBeforeEvent(entry) } if e.IsFiltered() { @@ -574,7 +561,7 @@ func (e *Enforcer) SavePolicy() error { if shouldLog { entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return err } @@ -582,7 +569,7 @@ func (e *Enforcer) SavePolicy() error { if shouldLog { entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return err } @@ -596,14 +583,14 @@ func (e *Enforcer) SavePolicy() error { if shouldLog { entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return err } if shouldLog { entry.Duration = time.Since(handle.StartTime) - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return nil @@ -646,7 +633,7 @@ func (e *Enforcer) EnableEnforce(enable bool) { // EnableLog changes whether Casbin will log messages to the Logger. func (e *Enforcer) EnableLog(enable bool) { - e.logger.EnableLog(enable) + e.logger.Enable(enable) } // IsLogEnabled returns the current logger's enabled status. @@ -751,7 +738,7 @@ func (e *Enforcer) enforce(matcher string, explains *[]string, rvals ...interfac entry.Domain = toString(rvals[3]) } - handle = e.eventLogger.OnBeforeEvent(entry) + handle = e.logger.OnBeforeEvent(entry) } defer func() { @@ -760,7 +747,7 @@ func (e *Enforcer) enforce(matcher string, explains *[]string, rvals ...interfac entry.Allowed = ok entry.Matched = logExplains entry.Error = err - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } }() @@ -980,7 +967,7 @@ func (e *Enforcer) enforce(matcher string, explains *[]string, rvals ...interfac if effect == effector.Allow { result = true } - e.logger.LogEnforce(expString, rvals, result, logExplains) + // Note: LogEnforce was removed as enforcement is now logged via OnBeforeEvent/OnAfterEvent. return result, nil } @@ -1165,7 +1152,32 @@ func generateEvalFunction(functions map[string]govaluate.ExpressionFunction, par } } -// toString converts an interface{} to string for logging +// logEventStart initializes event logging for a given event type. +// Returns entry, handle, and shouldLog flag. +func (e *Enforcer) logEventStart(eventType log.EventType) (*log.LogEntry, *log.Handle, bool) { + shouldLog := e.shouldLog(eventType) + if !shouldLog { + return nil, nil, false + } + + entry := &log.LogEntry{ + Type: eventType, + Timestamp: time.Now(), + Attributes: make(map[string]interface{}), + } + handle := e.logger.OnBeforeEvent(entry) + return entry, handle, true +} + +// logEventEnd finalizes event logging. +func (e *Enforcer) logEventEnd(handle *log.Handle, entry *log.LogEntry, shouldLog bool) { + if shouldLog && entry != nil && handle != nil { + entry.Duration = time.Since(handle.StartTime) + e.logger.OnAfterEvent(handle, entry) + } +} + +// toString converts an interface{} to string for logging. func toString(v interface{}) string { if s, ok := v.(string); ok { return s diff --git a/enforcer_cached.go b/enforcer_cached.go index b9f4b4240..d48b6e140 100644 --- a/enforcer_cached.go +++ b/enforcer_cached.go @@ -177,7 +177,7 @@ func GetCacheKey(params ...interface{}) (string, bool) { func (e *CachedEnforcer) ClearPolicy() { if atomic.LoadInt32(&e.enableCache) != 0 { if err := e.cache.Clear(); err != nil { - e.logger.LogError(err, "clear cache failed") + // Note: LogError was removed as the new Logger interface is event-based. return } } diff --git a/internal_api.go b/internal_api.go index 3d4280ada..1e5e86a61 100644 --- a/internal_api.go +++ b/internal_api.go @@ -345,7 +345,7 @@ func (e *Enforcer) addPolicy(sec string, ptype string, rule []string) (bool, err RuleCount: 1, Attributes: make(map[string]interface{}), } - handle = e.eventLogger.OnBeforeEvent(entry) + handle = e.logger.OnBeforeEvent(entry) } ok, err := e.addPolicyWithoutNotify(sec, ptype, rule) @@ -353,7 +353,7 @@ func (e *Enforcer) addPolicy(sec string, ptype string, rule []string) (bool, err if shouldLog { entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return ok, err } @@ -368,14 +368,14 @@ func (e *Enforcer) addPolicy(sec string, ptype string, rule []string) (bool, err if shouldLog { entry.Duration = time.Since(handle.StartTime) entry.Error = notifyErr - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return true, notifyErr } if shouldLog { entry.Duration = time.Since(handle.StartTime) - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return true, nil @@ -399,7 +399,7 @@ func (e *Enforcer) addPolicies(sec string, ptype string, rules [][]string, autoR RuleCount: len(rules), Attributes: make(map[string]interface{}), } - handle = e.eventLogger.OnBeforeEvent(entry) + handle = e.logger.OnBeforeEvent(entry) } ok, err := e.addPoliciesWithoutNotify(sec, ptype, rules, autoRemoveRepeat) @@ -407,7 +407,7 @@ func (e *Enforcer) addPolicies(sec string, ptype string, rules [][]string, autoR if shouldLog { entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return ok, err } @@ -422,14 +422,14 @@ func (e *Enforcer) addPolicies(sec string, ptype string, rules [][]string, autoR if shouldLog { entry.Duration = time.Since(handle.StartTime) entry.Error = notifyErr - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return true, notifyErr } if shouldLog { entry.Duration = time.Since(handle.StartTime) - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return true, nil @@ -451,7 +451,7 @@ func (e *Enforcer) removePolicy(sec string, ptype string, rule []string) (bool, RuleCount: 1, Attributes: make(map[string]interface{}), } - handle = e.eventLogger.OnBeforeEvent(entry) + handle = e.logger.OnBeforeEvent(entry) } ok, err := e.removePolicyWithoutNotify(sec, ptype, rule) @@ -459,7 +459,7 @@ func (e *Enforcer) removePolicy(sec string, ptype string, rule []string) (bool, if shouldLog { entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return ok, err } @@ -474,14 +474,14 @@ func (e *Enforcer) removePolicy(sec string, ptype string, rule []string) (bool, if shouldLog { entry.Duration = time.Since(handle.StartTime) entry.Error = notifyErr - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return true, notifyErr } if shouldLog { entry.Duration = time.Since(handle.StartTime) - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return true, nil @@ -502,7 +502,7 @@ func (e *Enforcer) updatePolicy(sec string, ptype string, oldRule []string, newR RuleCount: 1, Attributes: make(map[string]interface{}), } - handle = e.eventLogger.OnBeforeEvent(entry) + handle = e.logger.OnBeforeEvent(entry) } ok, err := e.updatePolicyWithoutNotify(sec, ptype, oldRule, newRule) @@ -510,7 +510,7 @@ func (e *Enforcer) updatePolicy(sec string, ptype string, oldRule []string, newR if shouldLog { entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return ok, err } @@ -525,14 +525,14 @@ func (e *Enforcer) updatePolicy(sec string, ptype string, oldRule []string, newR if shouldLog { entry.Duration = time.Since(handle.StartTime) entry.Error = notifyErr - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return true, notifyErr } if shouldLog { entry.Duration = time.Since(handle.StartTime) - e.eventLogger.OnAfterEvent(handle, entry) + e.logger.OnAfterEvent(handle, entry) } return true, nil diff --git a/log/default_event_logger.go b/log/default_event_logger.go deleted file mode 100644 index b400e4da1..000000000 --- a/log/default_event_logger.go +++ /dev/null @@ -1,49 +0,0 @@ -// Copyright 2024 The casbin Authors. All Rights Reserved. -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -package log - -// DefaultEventLogger is a no-op event logger implementation -type DefaultEventLogger struct { - enabled bool - subscribe []EventType -} - -// NewDefaultEventLogger creates a new DefaultEventLogger -func NewDefaultEventLogger() *DefaultEventLogger { - return &DefaultEventLogger{ - enabled: false, - subscribe: nil, // nil means subscribe to all events - } -} - -func (l *DefaultEventLogger) Enable(enabled bool) { - l.enabled = enabled -} - -func (l *DefaultEventLogger) IsEnabled() bool { - return l.enabled -} - -func (l *DefaultEventLogger) Subscribe() []EventType { - return l.subscribe -} - -func (l *DefaultEventLogger) OnBeforeEvent(entry *LogEntry) *Handle { - return NewHandle() -} - -func (l *DefaultEventLogger) OnAfterEvent(handle *Handle, entry *LogEntry) { - // Default implementation does nothing -} diff --git a/log/default_logger.go b/log/default_logger.go index 9994f390b..06f3a516c 100644 --- a/log/default_logger.go +++ b/log/default_logger.go @@ -1,4 +1,4 @@ -// Copyright 2018 The casbin Authors. All Rights Reserved. +// Copyright 2024 The casbin Authors. All Rights Reserved. // // Licensed under the Apache License, Version 2.0 (the "License"); // you may not use this file except in compliance with the License. @@ -14,91 +14,41 @@ package log -import ( - "fmt" - "log" - "strings" -) - -// DefaultLogger is the implementation for a Logger using golang log. +// DefaultLogger is a no-op logger implementation. type DefaultLogger struct { - enabled bool -} - -func (l *DefaultLogger) EnableLog(enable bool) { - l.enabled = enable -} - -func (l *DefaultLogger) IsEnabled() bool { - return l.enabled + enabled bool + subscribe []EventType } -func (l *DefaultLogger) LogModel(model [][]string) { - if !l.enabled { - return - } - var str strings.Builder - str.WriteString("Model: ") - for _, v := range model { - str.WriteString(fmt.Sprintf("%v\n", v)) +// NewDefaultLogger creates a new DefaultLogger. +func NewDefaultLogger() *DefaultLogger { + return &DefaultLogger{ + enabled: false, + subscribe: nil, // nil means subscribe to all events. } - - log.Println(str.String()) } -func (l *DefaultLogger) LogEnforce(matcher string, request []interface{}, result bool, explains [][]string) { - if !l.enabled { - return - } - - var reqStr strings.Builder - reqStr.WriteString("Request: ") - for i, rval := range request { - if i != len(request)-1 { - reqStr.WriteString(fmt.Sprintf("%v, ", rval)) - } else { - reqStr.WriteString(fmt.Sprintf("%v", rval)) - } - } - reqStr.WriteString(fmt.Sprintf(" ---> %t\n", result)) - - reqStr.WriteString("Hit Policy: ") - for i, pval := range explains { - if i != len(explains)-1 { - reqStr.WriteString(fmt.Sprintf("%v, ", pval)) - } else { - reqStr.WriteString(fmt.Sprintf("%v \n", pval)) - } - } - - log.Println(reqStr.String()) +// Enable turns the logger on or off. +func (l *DefaultLogger) Enable(enabled bool) { + l.enabled = enabled } -func (l *DefaultLogger) LogPolicy(policy map[string][][]string) { - if !l.enabled { - return - } - - var str strings.Builder - str.WriteString("Policy: ") - for k, v := range policy { - str.WriteString(fmt.Sprintf("%s : %v\n", k, v)) - } - - log.Println(str.String()) +// IsEnabled returns whether the logger is enabled. +func (l *DefaultLogger) IsEnabled() bool { + return l.enabled } -func (l *DefaultLogger) LogRole(roles []string) { - if !l.enabled { - return - } +// Subscribe returns the list of event types this logger is interested in. +func (l *DefaultLogger) Subscribe() []EventType { + return l.subscribe +} - log.Println("Roles: ", strings.Join(roles, "\n")) +// OnBeforeEvent is called before an event occurs. +func (l *DefaultLogger) OnBeforeEvent(entry *LogEntry) *Handle { + return NewHandle() } -func (l *DefaultLogger) LogError(err error, msg ...string) { - if !l.enabled { - return - } - log.Println(msg, err) +// OnAfterEvent is called after an event completes. +func (l *DefaultLogger) OnAfterEvent(handle *Handle, entry *LogEntry) { + // Default implementation does nothing. } diff --git a/log/event_logger.go b/log/event_logger.go deleted file mode 100644 index 619b022b8..000000000 --- a/log/event_logger.go +++ /dev/null @@ -1,111 +0,0 @@ -// Copyright 2024 The casbin Authors. All Rights Reserved. -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -package log - -import ( - "time" -) - -// ==================== Event Types ==================== - -// EventType represents the type of event being logged -type EventType string - -const ( - EventEnforce EventType = "enforce" - EventPolicyAdd EventType = "policy.add" - EventPolicyRemove EventType = "policy.remove" - EventPolicyUpdate EventType = "policy.update" - EventPolicyLoad EventType = "policy.load" - EventPolicySave EventType = "policy.save" - EventModelLoad EventType = "model.load" - EventRoleAdd EventType = "role.add" - EventRoleRemove EventType = "role.remove" -) - -// ==================== Handle ==================== - -// Handle is passed from OnBeforeEvent to OnAfterEvent -// Logger implementations can store custom data in the Store field -type Handle struct { - // StartTime records when the event started - StartTime time.Time - - // Store allows logger implementations to attach custom data - // e.g., OpenTelemetry can store Span, context, etc. - Store map[string]interface{} -} - -// NewHandle creates a new Handle with initialized fields -func NewHandle() *Handle { - return &Handle{ - StartTime: time.Now(), - Store: make(map[string]interface{}), - } -} - -// ==================== Log Entry ==================== - -// LogEntry contains all information about an event -type LogEntry struct { - // Event info - Type EventType - Timestamp time.Time - Duration time.Duration // Filled in OnAfterEvent - - // Enforce related - Request []interface{} - Subject string - Object string - Action string - Domain string - Allowed bool - Matched [][]string - - // Policy/Role related - Operation string - Rules [][]string - RuleCount int - - // Error info - Error error - - // Custom attributes (can store context.Context, trace IDs, etc.) - Attributes map[string]interface{} -} - -// ==================== Event Logger Interface ==================== - -// EventLogger is the unified interface for logging, tracing, and metrics -type EventLogger interface { - // Enable turns the logger on or off - Enable(enabled bool) - - // IsEnabled returns whether the logger is enabled - IsEnabled() bool - - // Subscribe returns the list of event types this logger is interested in - // Return nil or empty slice to subscribe to all events - // Return specific event types to filter events - Subscribe() []EventType - - // OnBeforeEvent is called before an event occurs - // Returns a Handle that will be passed to OnAfterEvent - OnBeforeEvent(entry *LogEntry) *Handle - - // OnAfterEvent is called after an event completes - // The Handle from OnBeforeEvent is passed back along with the updated entry - OnAfterEvent(handle *Handle, entry *LogEntry) -} diff --git a/log/log_util.go b/log/log_util.go deleted file mode 100644 index 7edabf899..000000000 --- a/log/log_util.go +++ /dev/null @@ -1,52 +0,0 @@ -// Copyright 2017 The casbin Authors. All Rights Reserved. -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -package log - -var logger Logger = &DefaultLogger{} - -// SetLogger sets the current logger. -func SetLogger(l Logger) { - logger = l -} - -// GetLogger returns the current logger. -func GetLogger() Logger { - return logger -} - -// LogModel logs the model information. -func LogModel(model [][]string) { - logger.LogModel(model) -} - -// LogEnforce logs the enforcer information. -func LogEnforce(matcher string, request []interface{}, result bool, explains [][]string) { - logger.LogEnforce(matcher, request, result, explains) -} - -// LogRole log info related to role. -func LogRole(roles []string) { - logger.LogRole(roles) -} - -// LogPolicy logs the policy information. -func LogPolicy(policy map[string][][]string) { - logger.LogPolicy(policy) -} - -// LogError logs the error information. -func LogError(err error, msg ...string) { - logger.LogError(err, msg...) -} diff --git a/log/log_util_test.go b/log/log_util_test.go deleted file mode 100644 index 296b6afac..000000000 --- a/log/log_util_test.go +++ /dev/null @@ -1,56 +0,0 @@ -// Copyright 2017 The casbin Authors. All Rights Reserved. -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -package log - -import ( - "testing" - - "github.com/casbin/casbin/v3/log/mocks" - - "github.com/golang/mock/gomock" -) - -func TestLog(t *testing.T) { - ctrl := gomock.NewController(t) - defer ctrl.Finish() - - m := mocks.NewMockLogger(ctrl) - SetLogger(m) - - m.EXPECT().EnableLog(true) - m.EXPECT().IsEnabled() - - logger.EnableLog(true) - logger.IsEnabled() - - policy := map[string][][]string{} - m.EXPECT().LogPolicy(policy) - LogPolicy(policy) - - var model [][]string - m.EXPECT().LogModel(model) - LogModel(model) - - matcher := "my_matcher" - request := []interface{}{"bob"} - result := true - var explains [][]string - m.EXPECT().LogEnforce(matcher, request, result, explains) - LogEnforce(matcher, request, result, explains) - - var roles []string - m.EXPECT().LogRole(roles) - LogRole(roles) -} diff --git a/log/logger.go b/log/logger.go index 37841617a..4a25cce15 100644 --- a/log/logger.go +++ b/log/logger.go @@ -1,4 +1,4 @@ -// Copyright 2018 The casbin Authors. All Rights Reserved. +// Copyright 2024 The casbin Authors. All Rights Reserved. // // Licensed under the Apache License, Version 2.0 (the "License"); // you may not use this file except in compliance with the License. @@ -14,28 +14,100 @@ package log +import ( + "time" +) + //go:generate mockgen -destination=./mocks/mock_logger.go -package=mocks github.com/casbin/casbin/v3/log Logger -// Logger is the logging interface implementation. -type Logger interface { - // EnableLog controls whether print the message. - EnableLog(bool) +// ==================== Event Types ==================== - // IsEnabled returns if logger is enabled. - IsEnabled() bool +// EventType represents the type of event being logged. +type EventType string + +const ( + EventEnforce EventType = "enforce" + EventPolicyAdd EventType = "policy.add" + EventPolicyRemove EventType = "policy.remove" + EventPolicyUpdate EventType = "policy.update" + EventPolicyLoad EventType = "policy.load" + EventPolicySave EventType = "policy.save" + EventModelLoad EventType = "model.load" + EventRoleAdd EventType = "role.add" + EventRoleRemove EventType = "role.remove" +) + +// ==================== Handle ==================== + +// Handle is passed from OnBeforeEvent to OnAfterEvent. +// Logger implementations can store custom data in the Store field. +type Handle struct { + // StartTime records when the event started. + StartTime time.Time + + // Store allows logger implementations to attach custom data. + // e.g., OpenTelemetry can store Span, context, etc. + Store map[string]interface{} +} + +// NewHandle creates a new Handle with initialized fields. +func NewHandle() *Handle { + return &Handle{ + StartTime: time.Now(), + Store: make(map[string]interface{}), + } +} - // LogModel log info related to model. - LogModel(model [][]string) +// ==================== Log Entry ==================== - // LogEnforce log info related to enforce. - LogEnforce(matcher string, request []interface{}, result bool, explains [][]string) +// LogEntry contains all information about an event. +type LogEntry struct { + // Event info. + Type EventType + Timestamp time.Time + Duration time.Duration // Filled in OnAfterEvent. + + // Enforce related. + Request []interface{} + Subject string + Object string + Action string + Domain string + Allowed bool + Matched [][]string + + // Policy/Role related. + Operation string + Rules [][]string + RuleCount int + + // Error info. + Error error + + // Custom attributes (can store context.Context, trace IDs, etc.). + Attributes map[string]interface{} +} + +// ==================== Logger Interface ==================== + +// Logger is the unified interface for logging, tracing, and metrics. +type Logger interface { + // Enable turns the logger on or off. + Enable(enabled bool) + + // IsEnabled returns whether the logger is enabled. + IsEnabled() bool - // LogRole log info related to role. - LogRole(roles []string) + // Subscribe returns the list of event types this logger is interested in. + // Return nil or empty slice to subscribe to all events. + // Return specific event types to filter events. + Subscribe() []EventType - // LogPolicy log info related to policy. - LogPolicy(policy map[string][][]string) + // OnBeforeEvent is called before an event occurs. + // Returns a Handle that will be passed to OnAfterEvent. + OnBeforeEvent(entry *LogEntry) *Handle - // LogError log info relate to error - LogError(err error, msg ...string) + // OnAfterEvent is called after an event completes. + // The Handle from OnBeforeEvent is passed back along with the updated entry. + OnAfterEvent(handle *Handle, entry *LogEntry) } diff --git a/log/event_logger_test.go b/log/logger_test.go similarity index 70% rename from log/event_logger_test.go rename to log/logger_test.go index d99aaac9e..25e3e832a 100644 --- a/log/event_logger_test.go +++ b/log/logger_test.go @@ -19,47 +19,55 @@ import ( "time" ) -// TestEventLogger is a test logger implementation that captures events -type TestEventLogger struct { +// TestLogger is a test logger implementation that captures events. +type TestLogger struct { enabled bool subscribe []EventType events []*LogEntry } -func NewTestEventLogger(subscribe ...EventType) *TestEventLogger { - return &TestEventLogger{ +// NewTestLogger creates a new TestLogger. +func NewTestLogger(subscribe ...EventType) *TestLogger { + return &TestLogger{ enabled: true, subscribe: subscribe, events: make([]*LogEntry, 0), } } -func (l *TestEventLogger) Enable(enabled bool) { +// Enable turns the logger on or off. +func (l *TestLogger) Enable(enabled bool) { l.enabled = enabled } -func (l *TestEventLogger) IsEnabled() bool { +// IsEnabled returns whether the logger is enabled. +func (l *TestLogger) IsEnabled() bool { return l.enabled } -func (l *TestEventLogger) Subscribe() []EventType { +// Subscribe returns the list of event types this logger is interested in. +func (l *TestLogger) Subscribe() []EventType { return l.subscribe } -func (l *TestEventLogger) OnBeforeEvent(entry *LogEntry) *Handle { +// OnBeforeEvent is called before an event occurs. +func (l *TestLogger) OnBeforeEvent(entry *LogEntry) *Handle { return NewHandle() } -func (l *TestEventLogger) OnAfterEvent(handle *Handle, entry *LogEntry) { - // Store a copy of the entry +// OnAfterEvent is called after an event completes. +func (l *TestLogger) OnAfterEvent(handle *Handle, entry *LogEntry) { + // Store a copy of the entry. l.events = append(l.events, entry) } -func (l *TestEventLogger) GetEvents() []*LogEntry { +// GetEvents returns all captured events. +func (l *TestLogger) GetEvents() []*LogEntry { return l.events } -func (l *TestEventLogger) Clear() { +// Clear clears all captured events. +func (l *TestLogger) Clear() { l.events = make([]*LogEntry, 0) } @@ -76,23 +84,23 @@ func TestNewHandle(t *testing.T) { } } -func TestDefaultEventLogger(t *testing.T) { - logger := NewDefaultEventLogger() - +func TestDefaultLogger(t *testing.T) { + logger := NewDefaultLogger() + if logger.IsEnabled() { - t.Error("DefaultEventLogger should be disabled by default") + t.Error("DefaultLogger should be disabled by default") } - + logger.Enable(true) if !logger.IsEnabled() { - t.Error("DefaultEventLogger should be enabled after Enable(true)") + t.Error("DefaultLogger should be enabled after Enable(true)") } - + if logger.Subscribe() != nil { - t.Error("DefaultEventLogger should subscribe to all events by default (nil)") + t.Error("DefaultLogger should subscribe to all events by default (nil)") } - - // Test that it doesn't panic when called + + // Test that it doesn't panic when called. entry := &LogEntry{ Type: EventEnforce, Timestamp: time.Now(), @@ -101,23 +109,23 @@ func TestDefaultEventLogger(t *testing.T) { if handle == nil { t.Error("OnBeforeEvent should return a handle") } - + logger.OnAfterEvent(handle, entry) } -func TestTestEventLogger(t *testing.T) { - logger := NewTestEventLogger(EventEnforce, EventPolicyAdd) - +func TestTestLogger(t *testing.T) { + logger := NewTestLogger(EventEnforce, EventPolicyAdd) + if !logger.IsEnabled() { - t.Error("TestEventLogger should be enabled by default") + t.Error("TestLogger should be enabled by default") } - + subscribe := logger.Subscribe() if len(subscribe) != 2 { t.Errorf("Expected 2 subscriptions, got %d", len(subscribe)) } - - // Test event capture + + // Test event capture. entry := &LogEntry{ Type: EventEnforce, Timestamp: time.Now(), @@ -126,20 +134,20 @@ func TestTestEventLogger(t *testing.T) { Action: "read", Allowed: true, } - + handle := logger.OnBeforeEvent(entry) entry.Duration = time.Since(handle.StartTime) logger.OnAfterEvent(handle, entry) - + events := logger.GetEvents() if len(events) != 1 { t.Errorf("Expected 1 event, got %d", len(events)) } - + if events[0].Type != EventEnforce { t.Errorf("Expected EventEnforce, got %v", events[0].Type) } - + if events[0].Subject != "alice" { t.Errorf("Expected subject 'alice', got %s", events[0].Subject) } @@ -157,7 +165,7 @@ func TestEventTypes(t *testing.T) { EventRoleAdd, EventRoleRemove, } - + for _, eventType := range types { if string(eventType) == "" { t.Errorf("Event type should not be empty: %v", eventType) @@ -182,19 +190,19 @@ func TestLogEntry(t *testing.T) { Error: nil, Attributes: make(map[string]interface{}), } - + if entry.Type != EventEnforce { t.Error("Entry type mismatch") } - + if entry.Subject != "alice" { t.Error("Entry subject mismatch") } - + if !entry.Allowed { t.Error("Entry should be allowed") } - + if entry.Duration < time.Millisecond { t.Error("Entry duration too short") } diff --git a/event_logger_test.go b/logger_integration_test.go similarity index 80% rename from event_logger_test.go rename to logger_integration_test.go index f978ec47c..5a31fe4d6 100644 --- a/event_logger_test.go +++ b/logger_integration_test.go @@ -20,55 +20,55 @@ import ( "github.com/casbin/casbin/v3/log" ) -// TestEventLogger is a test logger implementation that captures events -type TestEventLogger struct { +// TestLogger is a test logger implementation that captures events +type TestLogger struct { enabled bool subscribe []log.EventType events []*log.LogEntry } -func NewTestEventLogger(subscribe ...log.EventType) *TestEventLogger { - return &TestEventLogger{ +func NewTestLogger(subscribe ...log.EventType) *TestLogger { + return &TestLogger{ enabled: true, subscribe: subscribe, events: make([]*log.LogEntry, 0), } } -func (l *TestEventLogger) Enable(enabled bool) { +func (l *TestLogger) Enable(enabled bool) { l.enabled = enabled } -func (l *TestEventLogger) IsEnabled() bool { +func (l *TestLogger) IsEnabled() bool { return l.enabled } -func (l *TestEventLogger) Subscribe() []log.EventType { +func (l *TestLogger) Subscribe() []log.EventType { return l.subscribe } -func (l *TestEventLogger) OnBeforeEvent(entry *log.LogEntry) *log.Handle { +func (l *TestLogger) OnBeforeEvent(entry *log.LogEntry) *log.Handle { return log.NewHandle() } -func (l *TestEventLogger) OnAfterEvent(handle *log.Handle, entry *log.LogEntry) { +func (l *TestLogger) OnAfterEvent(handle *log.Handle, entry *log.LogEntry) { // Store a copy of the entry l.events = append(l.events, entry) } -func (l *TestEventLogger) GetEvents() []*log.LogEntry { +func (l *TestLogger) GetEvents() []*log.LogEntry { return l.events } -func (l *TestEventLogger) Clear() { +func (l *TestLogger) Clear() { l.events = make([]*log.LogEntry, 0) } -func TestEnforcerWithEventLogger(t *testing.T) { +func TestEnforcerWithLogger(t *testing.T) { e, _ := NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv") - logger := NewTestEventLogger(log.EventEnforce) - e.SetEventLogger(logger) + logger := NewTestLogger(log.EventEnforce) + e.SetLogger(logger) // Test enforce result, _ := e.Enforce("alice", "data1", "read") @@ -114,8 +114,8 @@ func TestEnforcerWithEventLogger(t *testing.T) { func TestEnforcerPolicyAddEvent(t *testing.T) { e, _ := NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv") - logger := NewTestEventLogger(log.EventPolicyAdd) - e.SetEventLogger(logger) + logger := NewTestLogger(log.EventPolicyAdd) + e.SetLogger(logger) // Test add policy ok, _ := e.AddPolicy("eve", "data3", "read") @@ -149,8 +149,8 @@ func TestEnforcerPolicyAddEvent(t *testing.T) { func TestEnforcerPolicyRemoveEvent(t *testing.T) { e, _ := NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv") - logger := NewTestEventLogger(log.EventPolicyRemove) - e.SetEventLogger(logger) + logger := NewTestLogger(log.EventPolicyRemove) + e.SetLogger(logger) // Test remove policy ok, _ := e.RemovePolicy("alice", "data1", "read") @@ -176,8 +176,8 @@ func TestEnforcerPolicyRemoveEvent(t *testing.T) { func TestEnforcerLoadPolicyEvent(t *testing.T) { e, _ := NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv") - logger := NewTestEventLogger(log.EventPolicyLoad) - e.SetEventLogger(logger) + logger := NewTestLogger(log.EventPolicyLoad) + e.SetLogger(logger) // Test load policy err := e.LoadPolicy() @@ -204,12 +204,12 @@ func TestEnforcerLoadPolicyEvent(t *testing.T) { } } -func TestEventLoggerSubscription(t *testing.T) { +func TestLoggerSubscription(t *testing.T) { e, _ := NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv") // Subscribe only to enforce events - logger := NewTestEventLogger(log.EventEnforce) - e.SetEventLogger(logger) + logger := NewTestLogger(log.EventEnforce) + e.SetLogger(logger) // Enforce should be logged e.Enforce("alice", "data1", "read") @@ -227,12 +227,12 @@ func TestEventLoggerSubscription(t *testing.T) { } } -func TestEventLoggerSubscribeToAll(t *testing.T) { +func TestLoggerSubscribeToAll(t *testing.T) { e, _ := NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv") // Subscribe to all events (pass no arguments) - logger := NewTestEventLogger() - e.SetEventLogger(logger) + logger := NewTestLogger() + e.SetLogger(logger) // Multiple operations e.Enforce("alice", "data1", "read") @@ -258,12 +258,12 @@ func TestEventLoggerSubscribeToAll(t *testing.T) { } } -func TestEventLoggerDisabled(t *testing.T) { +func TestLoggerDisabled(t *testing.T) { e, _ := NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv") - logger := NewTestEventLogger(log.EventEnforce) + logger := NewTestLogger(log.EventEnforce) logger.Enable(false) - e.SetEventLogger(logger) + e.SetLogger(logger) // This should not be logged e.Enforce("alice", "data1", "read") diff --git a/model/model.go b/model/model.go index 3f76010db..eabfe851a 100644 --- a/model/model.go +++ b/model/model.go @@ -77,7 +77,7 @@ func (model Model) AddDef(sec string, key string, value string) bool { ast.Value = value ast.PolicyMap = make(map[string]int) ast.FieldIndexMap = make(map[string]int) - ast.setLogger(model.GetLogger()) + // Note: setLogger call removed as GetLogger() now returns nil. if sec == "r" || sec == "p" { ast.Tokens = strings.Split(ast.Value, ",") @@ -130,24 +130,22 @@ func loadSection(model Model, cfg config.ConfigInterface, sec string) { } // SetLogger sets the model's logger. +// Note: This method is kept for backward compatibility but no longer sets anything. +// The new Logger interface is event-based and used only in the Enforcer. func (model Model) SetLogger(logger log.Logger) { - for _, astMap := range model { - for _, ast := range astMap { - ast.logger = logger - } - } - model["logger"] = AssertionMap{"logger": &Assertion{logger: logger}} + // No-op: The new Logger interface doesn't support model-level logging. } // GetLogger returns the model's logger. +// Note: This method is kept for backward compatibility but always returns nil. +// The new Logger interface is event-based and used only in the Enforcer. func (model Model) GetLogger() log.Logger { - return model["logger"]["logger"].logger + return nil } // NewModel creates an empty model. func NewModel() Model { m := make(Model) - m.SetLogger(&log.DefaultLogger{}) return m } @@ -228,23 +226,10 @@ func (model Model) GetAssertion(sec string, ptype string) (*Assertion, error) { } // PrintModel prints the model to the log. +// Note: This method is kept for backward compatibility but does nothing. +// The new Logger interface is event-based and doesn't support model printing. func (model Model) PrintModel() { - if !model.GetLogger().IsEnabled() { - return - } - - var modelInfo [][]string - for k, v := range model { - if k == "logger" { - continue - } - - for i, j := range v { - modelInfo = append(modelInfo, []string{k, i, j.Value}) - } - } - - model.GetLogger().LogModel(modelInfo) + // No-op: GetLogger() now returns nil and the new Logger doesn't support model printing. } func (model Model) SortPoliciesBySubjectHierarchy() error { @@ -418,7 +403,7 @@ func (model Model) Copy() Model { newModel[sec] = newAstMap } - newModel.SetLogger(model.GetLogger()) + // Note: SetLogger call removed as it's now a no-op. return newModel } diff --git a/model/policy.go b/model/policy.go index 9b7c66c5c..6506e34d9 100644 --- a/model/policy.go +++ b/model/policy.go @@ -90,34 +90,10 @@ func (model Model) BuildConditionalRoleLinks(condRmMap map[string]rbac.Condition } // PrintPolicy prints the policy to log. +// Note: This method is kept for backward compatibility but does nothing. +// The new Logger interface is event-based and doesn't support policy printing. func (model Model) PrintPolicy() { - if !model.GetLogger().IsEnabled() { - return - } - - policy := make(map[string][][]string) - - for key, ast := range model["p"] { - value, found := policy[key] - if found { - value = append(value, ast.Policy...) - policy[key] = value - } else { - policy[key] = ast.Policy - } - } - - for key, ast := range model["g"] { - value, found := policy[key] - if found { - value = append(value, ast.Policy...) - policy[key] = value - } else { - policy[key] = ast.Policy - } - } - - model.GetLogger().LogPolicy(policy) + // No-op: GetLogger() now returns nil and the new Logger doesn't support policy printing. } // ClearPolicy clears all current policy. diff --git a/rbac/default-role-manager/role_manager.go b/rbac/default-role-manager/role_manager.go index f5b6f17ff..87690831d 100644 --- a/rbac/default-role-manager/role_manager.go +++ b/rbac/default-role-manager/role_manager.go @@ -316,8 +316,10 @@ func (rm *RoleManagerImpl) AddDomainMatchingFunc(name string, fn rbac.MatchingFu } // SetLogger sets role manager's logger. +// Note: This method is kept for backward compatibility but no longer sets anything. +// The new Logger interface is event-based and used only in the Enforcer. func (rm *RoleManagerImpl) SetLogger(logger log.Logger) { - rm.logger = logger + // No-op: The new Logger interface doesn't support role manager logging. } // Clear clears all stored data and resets the role manager to the initial state. @@ -499,8 +501,7 @@ func (rm *RoleManagerImpl) PrintRoles() error { if !(rm.logger).IsEnabled() { return nil } - roles := rm.toString() - rm.logger.LogRole(roles) + // Note: LogRole was removed as the new Logger interface is event-based. return nil } @@ -562,8 +563,10 @@ func NewDomainManager(maxHierarchyLevel int) *DomainManager { } // SetLogger sets role manager's logger. +// Note: This method is kept for backward compatibility but no longer sets anything. +// The new Logger interface is event-based and used only in the Enforcer. func (dm *DomainManager) SetLogger(logger log.Logger) { - dm.logger = logger + // No-op: The new Logger interface doesn't support role manager logging. } // AddMatchingFunc support use pattern in g. @@ -774,8 +777,7 @@ func (dm *DomainManager) PrintRoles() error { return nil } - roles := dm.toString() - dm.logger.LogRole(roles) + // Note: LogRole was removed as the new Logger interface is event-based. return nil } @@ -908,7 +910,7 @@ func (crm *ConditionalRoleManager) getNextRoles(currentRole, nextRole *Role, dom passLinkConditionFunc, err := crm.checkLinkCondition(currentRole.name, nextRole.name, domains) if err != nil { - crm.logger.LogError(err, "hasLinkHelper LinkCondition Error") + // Note: LogError was removed as the new Logger interface is event-based. return false } @@ -948,7 +950,7 @@ func (crm *ConditionalRoleManager) GetRoles(name string, domains ...string) ([]s roleName := key.(string) passLinkConditionFunc, err := crm.checkLinkCondition(name, roleName, domains) if err != nil { - crm.logger.LogError(err, "getRoles LinkCondition Error") + // Note: LogError was removed as the new Logger interface is event-based. return true } @@ -972,7 +974,7 @@ func (crm *ConditionalRoleManager) GetUsers(name string, domains ...string) ([]s passLinkConditionFunc, err := crm.checkLinkCondition(userName, name, domains) if err != nil { - crm.logger.LogError(err, "getUsers LinkCondition Error") + // Note: LogError was removed as the new Logger interface is event-based. return true } @@ -1029,7 +1031,7 @@ func (crm *ConditionalRoleManager) getImplicitRolesHelper(roles map[string]*Role if _, ok := roleSet[roleName]; !ok { passLinkConditionFunc, err := crm.checkLinkCondition(role.name, roleName, domains) if err != nil { - crm.logger.LogError(err, "getImplicitRoles LinkCondition Error") + // Note: LogError was removed as the new Logger interface is event-based. return true } @@ -1059,7 +1061,7 @@ func (crm *ConditionalRoleManager) getImplicitUsersHelper(users map[string]*Role if _, ok := userSet[userName]; !ok { passLinkConditionFunc, err := crm.checkLinkCondition(userName, user.name, domains) if err != nil { - crm.logger.LogError(err, "getImplicitUsers LinkCondition Error") + // Note: LogError was removed as the new Logger interface is event-based. return true } From 4875694fd4ce2514dde7c50959691350c476fba0 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sun, 21 Dec 2025 12:30:47 +0000 Subject: [PATCH 8/8] Simplify hook code in business logic methods using defer pattern - Refactored LoadPolicy(), SavePolicy(), addPolicy(), addPolicies(), removePolicy(), and updatePolicy() - Now use logEventStart() and logEventEnd() with defer for cleaner code - Removed repetitive logging setup/teardown code from all instrumented methods - Business logic methods now have minimal hook code overhead - Removed unused time import from internal_api.go Co-authored-by: hsluoyz <3787410+hsluoyz@users.noreply.github.com> --- enforcer.go | 58 +++++-------------------- internal_api.go | 113 +++++++++--------------------------------------- 2 files changed, 32 insertions(+), 139 deletions(-) diff --git a/enforcer.go b/enforcer.go index e40d114fc..5f33b7037 100644 --- a/enforcer.go +++ b/enforcer.go @@ -357,46 +357,32 @@ func (e *Enforcer) ClearPolicy() { // LoadPolicy reloads the policy from file/database. func (e *Enforcer) LoadPolicy() error { - // Event logging setup - var entry *log.LogEntry - var handle *log.Handle - shouldLog := e.shouldLog(log.EventPolicyLoad) - + entry, handle, shouldLog := e.logEventStart(log.EventPolicyLoad) if shouldLog { - entry = &log.LogEntry{ - Type: log.EventPolicyLoad, - Timestamp: time.Now(), - Operation: "load", - Attributes: make(map[string]interface{}), - } - handle = e.logger.OnBeforeEvent(entry) + entry.Operation = "load" + defer func() { + if shouldLog { + entry.RuleCount = e.GetPolicyCount() + } + e.logEventEnd(handle, entry, shouldLog) + }() } newModel, err := e.loadPolicyFromAdapter(e.model) if err != nil { if shouldLog { - entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.logger.OnAfterEvent(handle, entry) } return err } err = e.applyModifiedModel(newModel) if err != nil { if shouldLog { - entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.logger.OnAfterEvent(handle, entry) } return err } - if shouldLog { - entry.Duration = time.Since(handle.StartTime) - entry.RuleCount = e.GetPolicyCount() - e.logger.OnAfterEvent(handle, entry) - } - return nil } @@ -540,36 +526,23 @@ func (e *Enforcer) IsFiltered() bool { // SavePolicy saves the current policy (usually after changed with Casbin API) back to file/database. func (e *Enforcer) SavePolicy() error { - // Event logging setup - var entry *log.LogEntry - var handle *log.Handle - shouldLog := e.shouldLog(log.EventPolicySave) - + entry, handle, shouldLog := e.logEventStart(log.EventPolicySave) if shouldLog { - entry = &log.LogEntry{ - Type: log.EventPolicySave, - Timestamp: time.Now(), - Operation: "save", - RuleCount: e.GetPolicyCount(), - Attributes: make(map[string]interface{}), - } - handle = e.logger.OnBeforeEvent(entry) + entry.Operation = "save" + entry.RuleCount = e.GetPolicyCount() + defer e.logEventEnd(handle, entry, shouldLog) } if e.IsFiltered() { err := errors.New("cannot save a filtered policy") if shouldLog { - entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.logger.OnAfterEvent(handle, entry) } return err } if err := e.adapter.SavePolicy(e.model); err != nil { if shouldLog { - entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.logger.OnAfterEvent(handle, entry) } return err } @@ -581,18 +554,11 @@ func (e *Enforcer) SavePolicy() error { err = e.watcher.Update() } if shouldLog { - entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.logger.OnAfterEvent(handle, entry) } return err } - if shouldLog { - entry.Duration = time.Since(handle.StartTime) - e.logger.OnAfterEvent(handle, entry) - } - return nil } diff --git a/internal_api.go b/internal_api.go index 1e5e86a61..d6d5a39ef 100644 --- a/internal_api.go +++ b/internal_api.go @@ -16,7 +16,6 @@ package casbin import ( "fmt" - "time" Err "github.com/casbin/casbin/v3/errors" "github.com/casbin/casbin/v3/log" @@ -331,29 +330,18 @@ func (e *Enforcer) updateFilteredPoliciesWithoutNotify(sec string, ptype string, // addPolicy adds a rule to the current policy. func (e *Enforcer) addPolicy(sec string, ptype string, rule []string) (bool, error) { - // Event logging setup - var entry *log.LogEntry - var handle *log.Handle - shouldLog := e.shouldLog(log.EventPolicyAdd) - + entry, handle, shouldLog := e.logEventStart(log.EventPolicyAdd) if shouldLog { - entry = &log.LogEntry{ - Type: log.EventPolicyAdd, - Timestamp: time.Now(), - Operation: "add", - Rules: [][]string{rule}, - RuleCount: 1, - Attributes: make(map[string]interface{}), - } - handle = e.logger.OnBeforeEvent(entry) + entry.Operation = "add" + entry.Rules = [][]string{rule} + entry.RuleCount = 1 + defer e.logEventEnd(handle, entry, shouldLog) } ok, err := e.addPolicyWithoutNotify(sec, ptype, rule) if !ok || err != nil { if shouldLog { - entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.logger.OnAfterEvent(handle, entry) } return ok, err } @@ -366,18 +354,11 @@ func (e *Enforcer) addPolicy(sec string, ptype string, rule []string) (bool, err notifyErr = e.watcher.Update() } if shouldLog { - entry.Duration = time.Since(handle.StartTime) entry.Error = notifyErr - e.logger.OnAfterEvent(handle, entry) } return true, notifyErr } - if shouldLog { - entry.Duration = time.Since(handle.StartTime) - e.logger.OnAfterEvent(handle, entry) - } - return true, nil } @@ -385,29 +366,18 @@ func (e *Enforcer) addPolicy(sec string, ptype string, rule []string) (bool, err // If autoRemoveRepeat == true, existing rules are automatically filtered // Otherwise, false is returned directly. func (e *Enforcer) addPolicies(sec string, ptype string, rules [][]string, autoRemoveRepeat bool) (bool, error) { - // Event logging setup - var entry *log.LogEntry - var handle *log.Handle - shouldLog := e.shouldLog(log.EventPolicyAdd) - + entry, handle, shouldLog := e.logEventStart(log.EventPolicyAdd) if shouldLog { - entry = &log.LogEntry{ - Type: log.EventPolicyAdd, - Timestamp: time.Now(), - Operation: "add", - Rules: rules, - RuleCount: len(rules), - Attributes: make(map[string]interface{}), - } - handle = e.logger.OnBeforeEvent(entry) + entry.Operation = "add" + entry.Rules = rules + entry.RuleCount = len(rules) + defer e.logEventEnd(handle, entry, shouldLog) } ok, err := e.addPoliciesWithoutNotify(sec, ptype, rules, autoRemoveRepeat) if !ok || err != nil { if shouldLog { - entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.logger.OnAfterEvent(handle, entry) } return ok, err } @@ -420,46 +390,28 @@ func (e *Enforcer) addPolicies(sec string, ptype string, rules [][]string, autoR notifyErr = e.watcher.Update() } if shouldLog { - entry.Duration = time.Since(handle.StartTime) entry.Error = notifyErr - e.logger.OnAfterEvent(handle, entry) } return true, notifyErr } - if shouldLog { - entry.Duration = time.Since(handle.StartTime) - e.logger.OnAfterEvent(handle, entry) - } - return true, nil } // removePolicy removes a rule from the current policy. func (e *Enforcer) removePolicy(sec string, ptype string, rule []string) (bool, error) { - // Event logging setup - var entry *log.LogEntry - var handle *log.Handle - shouldLog := e.shouldLog(log.EventPolicyRemove) - + entry, handle, shouldLog := e.logEventStart(log.EventPolicyRemove) if shouldLog { - entry = &log.LogEntry{ - Type: log.EventPolicyRemove, - Timestamp: time.Now(), - Operation: "remove", - Rules: [][]string{rule}, - RuleCount: 1, - Attributes: make(map[string]interface{}), - } - handle = e.logger.OnBeforeEvent(entry) + entry.Operation = "remove" + entry.Rules = [][]string{rule} + entry.RuleCount = 1 + defer e.logEventEnd(handle, entry, shouldLog) } ok, err := e.removePolicyWithoutNotify(sec, ptype, rule) if !ok || err != nil { if shouldLog { - entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.logger.OnAfterEvent(handle, entry) } return ok, err } @@ -472,45 +424,27 @@ func (e *Enforcer) removePolicy(sec string, ptype string, rule []string) (bool, notifyErr = e.watcher.Update() } if shouldLog { - entry.Duration = time.Since(handle.StartTime) entry.Error = notifyErr - e.logger.OnAfterEvent(handle, entry) } return true, notifyErr } - if shouldLog { - entry.Duration = time.Since(handle.StartTime) - e.logger.OnAfterEvent(handle, entry) - } - return true, nil } func (e *Enforcer) updatePolicy(sec string, ptype string, oldRule []string, newRule []string) (bool, error) { - // Event logging setup - var entry *log.LogEntry - var handle *log.Handle - shouldLog := e.shouldLog(log.EventPolicyUpdate) - + entry, handle, shouldLog := e.logEventStart(log.EventPolicyUpdate) if shouldLog { - entry = &log.LogEntry{ - Type: log.EventPolicyUpdate, - Timestamp: time.Now(), - Operation: "update", - Rules: [][]string{oldRule, newRule}, - RuleCount: 1, - Attributes: make(map[string]interface{}), - } - handle = e.logger.OnBeforeEvent(entry) + entry.Operation = "update" + entry.Rules = [][]string{oldRule, newRule} + entry.RuleCount = 1 + defer e.logEventEnd(handle, entry, shouldLog) } ok, err := e.updatePolicyWithoutNotify(sec, ptype, oldRule, newRule) if !ok || err != nil { if shouldLog { - entry.Duration = time.Since(handle.StartTime) entry.Error = err - e.logger.OnAfterEvent(handle, entry) } return ok, err } @@ -523,18 +457,11 @@ func (e *Enforcer) updatePolicy(sec string, ptype string, oldRule []string, newR notifyErr = e.watcher.Update() } if shouldLog { - entry.Duration = time.Since(handle.StartTime) entry.Error = notifyErr - e.logger.OnAfterEvent(handle, entry) } return true, notifyErr } - if shouldLog { - entry.Duration = time.Since(handle.StartTime) - e.logger.OnAfterEvent(handle, entry) - } - return true, nil }