[feature] refactor the Logger interface to support tracing + metrics + logs of structured JSON, Prometheus, OpenTelemetry

[hsluoyz]

Inside this repo, we only put the Logger interface and DefaultLogger (aka structured JSON) implementation here.

Prometheus Logger, OpenTelemetry Logger, etc. will be put in separated repos.

package casbin

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{}
}

// ==================== 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

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

// ==================== Default Logger ====================

// DefaultLogger is a no-op logger implementation
type DefaultLogger struct {
    enabled   bool
    subscribe []EventType
}

// NewDefaultLogger creates a new DefaultLogger
func NewDefaultLogger() *DefaultLogger {
    return &DefaultLogger{
        enabled:   false,
        subscribe: nil, // nil means subscribe to all events
    }
}

func (l *DefaultLogger) Enable(enabled bool) {
    l.enabled = enabled
}

func (l *DefaultLogger) IsEnabled() bool {
    return l.enabled
}

func (l *DefaultLogger) Subscribe() []EventType {
    return l.subscribe
}

func (l *DefaultLogger) SetSubscribe(events []EventType) {
    l.subscribe = events
}

func (l *DefaultLogger) OnBeforeEvent(entry *LogEntry) *Handle {
    return NewHandle()
}

func (l *DefaultLogger) OnAfterEvent(handle *Handle, entry *LogEntry) {
    // Default implementation does nothing
}

// ==================== Enforcer Integration ====================

type Enforcer struct {
    logger          Logger
    subscribeCache  map[EventType]bool // Cache for quick lookup
}

func (e *Enforcer) SetLogger(logger Logger) {
    e.logger = logger
    e.updateSubscribeCache()
}

func (e *Enforcer) updateSubscribeCache() {
    e.subscribeCache = make(map[EventType]bool)

    if e.logger == nil {
        return
    }

    events := e.logger.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 EventType) bool {
    if e.logger == nil || !e.logger.IsEnabled() {
        return false
    }

    // nil cache means subscribe to all events
    if e.subscribeCache == nil {
        return true
    }

    return e.subscribeCache[eventType]
}

func (e *Enforcer) Enforce(rvals ...interface{}) (bool, error) {
    var entry *LogEntry
    var handle *Handle

    shouldLog := e.shouldLog(EventEnforce)

    if shouldLog {
        entry = &LogEntry{
            Type:       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.logger.OnBeforeEvent(entry)
    }

    // Execute actual logic
    result, matched, err := e.enforceInternal(rvals...)

    if shouldLog {
        entry.Duration = time.Since(entry.Timestamp)
        entry.Allowed = result
        entry.Matched = matched
        entry.Error = err

        e.logger.OnAfterEvent(handle, entry)
    }

    return result, err
}

func (e *Enforcer) AddPolicy(rules ...[]string) (bool, error) {
    var entry *LogEntry
    var handle *Handle

    shouldLog := e.shouldLog(EventPolicyAdd)

    if shouldLog {
        entry = &LogEntry{
            Type:       EventPolicyAdd,
            Timestamp:  time.Now(),
            Operation:  "add",
            Rules:      rules,
            RuleCount:  len(rules),
            Attributes: make(map[string]interface{}),
        }

        handle = e.logger.OnBeforeEvent(entry)
    }

    result, err := e.addPolicyInternal(rules...)

    if shouldLog {
        entry.Duration = time.Since(entry.Timestamp)
        entry.Error = err

        e.logger.OnAfterEvent(handle, entry)
    }

    return result, err
}

func (e *Enforcer) LoadPolicy() error {
    var entry *LogEntry
    var handle *Handle

    shouldLog := e.shouldLog(EventPolicyLoad)

    if shouldLog {
        entry = &LogEntry{
            Type:       EventPolicyLoad,
            Timestamp:  time.Now(),
            Operation:  "load",
            Attributes: make(map[string]interface{}),
        }

        handle = e.logger.OnBeforeEvent(entry)
    }

    err := e.loadPolicyInternal()

    if shouldLog {
        entry.Duration = time.Since(entry.Timestamp)
        entry.RuleCount = e.GetPolicyCount()
        entry.Error = err

        e.logger.OnAfterEvent(handle, entry)
    }

    return err
}

// Placeholder methods
func (e *Enforcer) enforceInternal(rvals ...interface{}) (bool, [][]string, error) {
    return true, nil, nil
}

func (e *Enforcer) addPolicyInternal(rules ...[]string) (bool, error) {
    return true, nil
}

func (e *Enforcer) loadPolicyInternal() error {
    return nil
}

func (e *Enforcer) GetPolicyCount() int {
    return 0
}

func toString(v interface{}) string {
    if s, ok := v.(string); ok {
        return s
    }
    return ""
}

Logger Plugin Implementations

1. JSON Logger

package jsonlogger
import (

"encoding/json"

"io"

"sync"

"time"
"github.com/casbin/casbin/v2"

)
type JsonLogger struct {

mu        sync.RWMutex

enabled   bool

subscribe []casbin.EventType

writer    io.Writer

pretty    bool

}
type Option func(*JsonLogger)
func WithPretty(pretty bool) Option {

return func(l *JsonLogger) {

l.pretty = pretty

}

}
func WithSubscribe(events ...casbin.EventType) Option {

return func(l *JsonLogger) {

l.subscribe = events

}

}
func NewJsonLogger(writer io.Writer, opts ...Option) *JsonLogger {

l := &JsonLogger{

enabled:   true,

subscribe: nil,

writer:    writer,

pretty:    false,

}
for _, opt := range opts {
    opt(l)
}

return l

}
func (l *JsonLogger) Enable(enabled bool) {

l.mu.Lock()

defer l.mu.Unlock()

l.enabled = enabled

}
func (l *JsonLogger) IsEnabled() bool {

l.mu.RLock()

defer l.mu.RUnlock()

return l.enabled

}
func (l *JsonLogger) Subscribe() []casbin.EventType {

l.mu.RLock()

defer l.mu.RUnlock()

return l.subscribe

}
func (l *JsonLogger) OnBeforeEvent(entry *casbin.LogEntry) *casbin.Handle {

return casbin.NewHandle()

}
func (l *JsonLogger) OnAfterEvent(handle *casbin.Handle, entry *casbin.LogEntry) {

output := map[string]interface{}{

"type":        string(entry.Type),

"timestamp":   entry.Timestamp.Format(time.RFC3339Nano),

"duration_ms": float64(entry.Duration.Microseconds()) / 1000.0,

}
// Enforce fields
if entry.Type == casbin.EventEnforce {
    output["subject"] = entry.Subject
    output["object"] = entry.Object
    output["action"] = entry.Action
    output["allowed"] = entry.Allowed

    if entry.Domain != "" {
        output["domain"] = entry.Domain
    }
    if len(entry.Matched) > 0 {
        output["matched"] = entry.Matched
    }
}

// Policy fields
if entry.Operation != "" {
    output["operation"] = entry.Operation
}
if entry.RuleCount > 0 {
    output["rule_count"] = entry.RuleCount
}
if len(entry.Rules) > 0 && len(entry.Rules) <= 10 {
    output["rules"] = entry.Rules
}

// Error
if entry.Error != nil {
    output["error"] = entry.Error.Error()
}

// Custom attributes (exclude context)
for k, v := range entry.Attributes {
    if k != "context" {
        output["attr_"+k] = v
    }
}

l.mu.Lock()
defer l.mu.Unlock()

var data []byte
if l.pretty {
    data, _ = json.MarshalIndent(output, "", "  ")
} else {
    data, _ = json.Marshal(output)
}

l.writer.Write(data)
l.writer.Write([]byte("\n"))

}

2. Prometheus Logger

package promlogger
import (

"sync"

"time"
"github.com/casbin/casbin/v2"
"github.com/prometheus/client_golang/prometheus"
"github.com/prometheus/client_golang/prometheus/promauto"

)
type PrometheusLogger struct {

mu        sync.RWMutex

enabled   bool

subscribe []casbin.EventType
enforceTotal      *prometheus.CounterVec
enforceDuration   *prometheus.HistogramVec
policyOpsTotal    *prometheus.CounterVec
policyOpsDuration *prometheus.HistogramVec
policyRuleCount   prometheus.Gauge

}
type Option func(*PrometheusLogger)
func WithSubscribe(events ...casbin.EventType) Option {

return func(l *PrometheusLogger) {

l.subscribe = events

}

}
func NewPrometheusLogger(namespace string, opts ...Option) *PrometheusLogger {

l := &PrometheusLogger{

enabled:   true,

subscribe: nil,

}
for _, opt := range opts {
    opt(l)
}

l.enforceTotal = promauto.NewCounterVec(
    prometheus.CounterOpts{
        Namespace: namespace,
        Name:      "enforce_total",
        Help:      "Total number of enforce calls",
    },
    []string{"allowed", "error"},
)

l.enforceDuration = promauto.NewHistogramVec(
    prometheus.HistogramOpts{
        Namespace: namespace,
        Name:      "enforce_duration_seconds",
        Help:      "Duration of enforce calls in seconds",
        Buckets:   []float64{.0001, .0005, .001, .005, .01, .05, .1, .5, 1},
    },
    []string{"allowed"},
)

l.policyOpsTotal = promauto.NewCounterVec(
    prometheus.CounterOpts{
        Namespace: namespace,
        Name:      "policy_operations_total",
        Help:      "Total number of policy operations",
    },
    []string{"operation", "error"},
)

l.policyOpsDuration = promauto.NewHistogramVec(
    prometheus.HistogramOpts{
        Namespace: namespace,
        Name:      "policy_operations_duration_seconds",
        Help:      "Duration of policy operations in seconds",
        Buckets:   []float64{.001, .01, .1, .5, 1, 5, 10},
    },
    []string{"operation"},
)

l.policyRuleCount = promauto.NewGauge(
    prometheus.GaugeOpts{
        Namespace: namespace,
        Name:      "policy_rules_total",
        Help:      "Current number of policy rules",
    },
)

return l

}
func (l *PrometheusLogger) Enable(enabled bool) {

l.mu.Lock()

defer l.mu.Unlock()

l.enabled = enabled

}
func (l *PrometheusLogger) IsEnabled() bool {

l.mu.RLock()

defer l.mu.RUnlock()

return l.enabled

}
func (l *PrometheusLogger) Subscribe() []casbin.EventType {

l.mu.RLock()

defer l.mu.RUnlock()

return l.subscribe

}
func (l *PrometheusLogger) OnBeforeEvent(entry *casbin.LogEntry) *casbin.Handle {

return casbin.NewHandle()

}
func (l *PrometheusLogger) OnAfterEvent(handle *casbin.Handle, entry *casbin.LogEntry) {

duration := time.Since(handle.StartTime).Seconds()

hasError := boolStr(entry.Error != nil)
switch entry.Type {
case casbin.EventEnforce:
    allowed := boolStr(entry.Allowed)
    l.enforceTotal.WithLabelValues(allowed, hasError).Inc()
    l.enforceDuration.WithLabelValues(allowed).Observe(duration)

case casbin.EventPolicyAdd, casbin.EventPolicyRemove, casbin.EventPolicyUpdate,
    casbin.EventPolicyLoad, casbin.EventPolicySave:
    l.policyOpsTotal.WithLabelValues(entry.Operation, hasError).Inc()
    l.policyOpsDuration.WithLabelValues(entry.Operation).Observe(duration)

    if entry.Type == casbin.EventPolicyLoad && entry.Error == nil {
        l.policyRuleCount.Set(float64(entry.RuleCount))
    }
}

}
func boolStr(b bool) string {

if b {

return "true"

}

return "false"

}

3. OpenTelemetry Logger

package otellogger
import (

"context"

"sync"
"github.com/casbin/casbin/v2"
"go.opentelemetry.io/otel"
"go.opentelemetry.io/otel/attribute"
"go.opentelemetry.io/otel/codes"
"go.opentelemetry.io/otel/metric"
"go.opentelemetry.io/otel/trace"

)
const (

storeKeyContext = "otel.context"

storeKeySpan    = "otel.span"

)
type OTelLogger struct {

mu        sync.RWMutex

enabled   bool

subscribe []casbin.EventType
tracer trace.Tracer
meter  metric.Meter

enforceCounter metric.Int64Counter
enforceLatency metric.Float64Histogram
policyCounter  metric.Int64Counter
policyLatency  metric.Float64Histogram

}
type Option func(*OTelLogger)
func WithSubscribe(events ...casbin.EventType) Option {

return func(l *OTelLogger) {

l.subscribe = events

}

}
func WithTracerProvider(tp trace.TracerProvider) Option {

return func(l *OTelLogger) {

l.tracer = tp.Tracer("github.com/casbin/casbin")

}

}
func WithMeterProvider(mp metric.MeterProvider) Option {

return func(l *OTelLogger) {

l.meter = mp.Meter("github.com/casbin/casbin")

}

}
func NewOTelLogger(opts ...Option) (*OTelLogger, error) {

l := &OTelLogger{

enabled:   true,

subscribe: nil,

tracer:    otel.Tracer("github.com/casbin/casbin"),

meter:     otel.Meter("github.com/casbin/casbin"),

}
for _, opt := range opts {
    opt(l)
}

var err error

l.enforceCounter, err = l.meter.Int64Counter(
    "casbin.enforce.total",
    metric.WithDescription("Total enforce calls"),
)
if err != nil {
    return nil, err
}

l.enforceLatency, err = l.meter.Float64Histogram(
    "casbin.enforce.duration",
    metric.WithDescription("Enforce duration in milliseconds"),
    metric.WithUnit("ms"),
)
if err != nil {
    return nil, err
}

l.policyCounter, err = l.meter.Int64Counter(
    "casbin.policy.operations",
    metric.WithDescription("Policy operations total"),
)
if err != nil {
    return nil, err
}

l.policyLatency, err = l.meter.Float64Histogram(
    "casbin.policy.duration",
    metric.WithDescription("Policy operation duration in milliseconds"),
    metric.WithUnit("ms"),
)
if err != nil {
    return nil, err
}

return l, nil

}
func (l *OTelLogger) Enable(enabled bool) {

l.mu.Lock()

defer l.mu.Unlock()

l.enabled = enabled

}
func (l *OTelLogger) IsEnabled() bool {

l.mu.RLock()

defer l.mu.RUnlock()

return l.enabled

}
func (l *OTelLogger) Subscribe() []casbin.EventType {

l.mu.RLock()

defer l.mu.RUnlock()

return l.subscribe

}
func (l *OTelLogger) OnBeforeEvent(entry *casbin.LogEntry) *casbin.Handle {

handle := casbin.NewHandle()
// Get parent context from entry attributes
ctx := context.Background()
if c, ok := entry.Attributes["context"].(context.Context); ok {
    ctx = c
}

// Create span
spanName := "casbin." + string(entry.Type)
ctx, span := l.tracer.Start(ctx, spanName,
    trace.WithSpanKind(trace.SpanKindInternal),
)

// Set common attributes
span.SetAttributes(attribute.String("casbin.event_type", string(entry.Type)))

// Enforce specific attributes
if entry.Type == casbin.EventEnforce {
    span.SetAttributes(
        attribute.String("casbin.subject", entry.Subject),
        attribute.String("casbin.object", entry.Object),
        attribute.String("casbin.action", entry.Action),
    )
    if entry.Domain != "" {
        span.SetAttributes(attribute.String("casbin.domain", entry.Domain))
    }
}

// Policy specific attributes
if entry.Operation != "" {
    span.SetAttributes(attribute.String("casbin.operation", entry.Operation))
}

// Store context and span in handle
handle.Store[storeKeyContext] = ctx
handle.Store[storeKeySpan] = span

return handle

}
func (l *OTelLogger) OnAfterEvent(handle *casbin.Handle, entry *casbin.LogEntry) {

// Retrieve context and span from handle

ctx, _ := handle.Store[storeKeyContext].(context.Context)

if ctx == nil {

ctx = context.Background()

}
span, _ := handle.Store[storeKeySpan].(trace.Span)
if span == nil {
    return
}

durationMs := float64(entry.Duration.Microseconds()) / 1000.0

// Set result attributes and record metrics
switch entry.Type {
case casbin.EventEnforce:
    span.SetAttributes(attribute.Bool("casbin.allowed", entry.Allowed))

    attrs := metric.WithAttributes(
        attribute.Bool("allowed", entry.Allowed),
        attribute.Bool("error", entry.Error != nil),
    )
    l.enforceCounter.Add(ctx, 1, attrs)
    l.enforceLatency.Record(ctx, durationMs, attrs)

default:
    if entry.RuleCount > 0 {
        span.SetAttributes(attribute.Int("casbin.rule_count", entry.RuleCount))
    }

    attrs := metric.WithAttributes(
        attribute.String("operation", entry.Operation),
        attribute.Bool("error", entry.Error != nil),
    )
    l.policyCounter.Add(ctx, 1, attrs)
    l.policyLatency.Record(ctx, durationMs, attrs)
}

// Handle error
if entry.Error != nil {
    span.RecordError(entry.Error)
    span.SetStatus(codes.Error, entry.Error.Error())
} else {
    span.SetStatus(codes.Ok, "")
}

// End span
span.End()

}

Usage Examples

package main
import (

"os"
"github.com/casbin/casbin/v2"
jsonlogger "github.com/casbin/json-logger"
promlogger "github.com/casbin/prometheus-logger"
otellogger "github.com/casbin/otel-logger"

)
func main() {

e, _ := casbin.NewEnforcer("model.conf", "policy.csv")
// Example 1: JSON Logger - subscribe to enforce events only
jsonLog := jsonlogger.NewJsonLogger(os.Stdout,
    jsonlogger.WithSubscribe(casbin.EventEnforce),
    jsonlogger.WithPretty(true),
)
e.SetLogger(jsonLog)

// Example 2: Prometheus Logger - subscribe to enforce and policy events
promLog := promlogger.NewPrometheusLogger("casbin",
    promlogger.WithSubscribe(
        casbin.EventEnforce,
        casbin.EventPolicyAdd,
        casbin.EventPolicyRemove,
        casbin.EventPolicyLoad,
    ),
)
e.SetLogger(promLog)

// Example 3: OpenTelemetry Logger - subscribe to all events (default)
otelLog, _ := otellogger.NewOTelLogger()
e.SetLogger(otelLog)

// Example 4: OpenTelemetry Logger - subscribe to specific events
otelLog2, _ := otellogger.NewOTelLogger(
    otellogger.WithSubscribe(casbin.EventEnforce, casbin.EventPolicyLoad),
)
e.SetLogger(otelLog2)

// Execute
e.Enforce("alice", "data1", "read")
e.AddPolicy([]string{"bob", "data2", "write"})
e.LoadPolicy()

}

Interface Summary

Method	Description
Enable(bool)	Enable or disable the logger
IsEnabled() bool	Check if logger is enabled
Subscribe() []EventType	Return list of subscribed events (nil/empty = all)
OnBeforeEvent(*LogEntry) *Handle	Called before event, returns Handle
OnAfterEvent(*Handle, *LogEntry)	Called after event with Handle and updated entry