From ebbf8684a6defa784e833973b517e088f9c777d9 Mon Sep 17 00:00:00 2001 From: Paul Lorenz Date: Thu, 3 Sep 2026 17:18:29 -0400 Subject: [PATCH] Hold the policy enforcers' meters rather than resolving one per run. Fixes #4350 Registry.Meter is reference counted: every call takes a reference, including calls that find the meter already present, and only Dispose releases one. The enforcers resolved a meter inside Run, so each run took a reference it never shed. Disposing such a meter decrements the count instead of stopping it, so it leaves the registry and keeps sampling. - resolves each enforcer's meter once, where the enforcer is built, and holds it - holds the timers alongside, though Timer is not reference counted, so a reader is not left working out why one of two adjacent lookups was cached - supplies the metrics in the session enforcer test, which builds the enforcer directly to get a negative session timeout that NewSessionEnforcer refuses Per enforcement cycle rather than per event, so the growth was one reference per run. Unbounded over a controller's lifetime, but slow. grep -rnE '\.(Meter|Histogram)\([^)]*\)\.(Mark|Update)' finds this shape; there are no others left outside tests. --- .../internal/policy/api_session_enforcer.go | 12 +++++++-- .../internal/policy/revocation_enforcer.go | 12 +++++++-- .../policy/service_policy_enforcer.go | 27 ++++++++++++++----- .../internal/policy/session_enforcer_test.go | 9 +++++-- 4 files changed, 47 insertions(+), 13 deletions(-) diff --git a/controller/internal/policy/api_session_enforcer.go b/controller/internal/policy/api_session_enforcer.go index 939ab2ab0..918572753 100644 --- a/controller/internal/policy/api_session_enforcer.go +++ b/controller/internal/policy/api_session_enforcer.go @@ -21,6 +21,7 @@ import ( "time" "github.com/michaelquigley/pfxlog" + "github.com/openziti/metrics" "github.com/openziti/ziti/v2/common/runner" "github.com/openziti/ziti/v2/controller/change" "github.com/openziti/ziti/v2/controller/env" @@ -39,6 +40,11 @@ const ( type ApiSessionEnforcer struct { appEnv model.Env sessionTimeout time.Duration + // Resolved once and held. A Meter lookup takes a reference on every call and only Dispose releases + // one, so looking one up per run accumulates references and leaves the meter sampling after the + // registry is disposed. Timer is not reference counted, and is held here so the two read alike. + runTimer metrics.Timer + deleteMeter metrics.Meter *runner.BaseOperation } @@ -55,6 +61,8 @@ func NewSessionEnforcer(appEnv *env.AppEnv, frequency time.Duration, sessionTime return &ApiSessionEnforcer{ appEnv: appEnv, sessionTimeout: sessionTimeout, + runTimer: appEnv.GetMetricsRegistry().Timer(ApiSessionEnforcerRun), + deleteMeter: appEnv.GetMetricsRegistry().Meter(ApiSessionEnforcerDelete), BaseOperation: runner.NewBaseOperation("ApiSessionEnforcer", frequency), } } @@ -63,7 +71,7 @@ func (s *ApiSessionEnforcer) Run() error { startTime := time.Now() defer func() { - s.appEnv.GetMetricsRegistry().Timer(ApiSessionEnforcerRun).UpdateSince(startTime) + s.runTimer.UpdateSince(startTime) }() oldest := time.Now().Add(s.sessionTimeout * -1) @@ -108,7 +116,7 @@ func (s *ApiSessionEnforcer) Run() error { logrus.WithError(err).Errorf("failure while deleting expired api session: %v", id) } } - s.appEnv.GetMetricsRegistry().Meter(ApiSessionEnforcerDelete).Mark(int64(len(ids))) + s.deleteMeter.Mark(int64(len(ids))) } } diff --git a/controller/internal/policy/revocation_enforcer.go b/controller/internal/policy/revocation_enforcer.go index d08b42681..139bf175d 100644 --- a/controller/internal/policy/revocation_enforcer.go +++ b/controller/internal/policy/revocation_enforcer.go @@ -20,6 +20,7 @@ import ( "time" "github.com/michaelquigley/pfxlog" + "github.com/openziti/metrics" "github.com/openziti/ziti/v2/common/runner" "github.com/openziti/ziti/v2/controller/change" "github.com/openziti/ziti/v2/controller/command" @@ -38,6 +39,11 @@ const ( type RevocationEnforcer struct { appEnv *env.AppEnv dispatcher command.Dispatcher + // Resolved once and held. A Meter lookup takes a reference on every call and only Dispose releases + // one, so looking one up per run accumulates references and leaves the meter sampling after the + // registry is disposed. Timer is not reference counted, and is held here so the two read alike. + runTimer metrics.Timer + deleteMeter metrics.Meter *runner.BaseOperation } @@ -46,6 +52,8 @@ func NewRevocationEnforcer(appEnv *env.AppEnv, frequency time.Duration, dispatch return &RevocationEnforcer{ appEnv: appEnv, dispatcher: dispatcher, + runTimer: appEnv.GetMetricsRegistry().Timer(RevocationEnforcerRun), + deleteMeter: appEnv.GetMetricsRegistry().Meter(RevocationEnforcerDelete), BaseOperation: runner.NewBaseOperation("RevocationEnforcer", frequency), } } @@ -59,7 +67,7 @@ func (e *RevocationEnforcer) Run() error { startTime := time.Now() defer func() { - e.appEnv.GetMetricsRegistry().Timer(RevocationEnforcerRun).UpdateSince(startTime) + e.runTimer.UpdateSince(startTime) }() ctx := change.New().SetSourceType(RevocationEnforcerSource).SetChangeAuthorType(change.AuthorTypeController) @@ -72,7 +80,7 @@ func (e *RevocationEnforcer) Run() error { if total > 0 { pfxlog.Logger().Debugf("removed %d expired revocations", total) - e.appEnv.GetMetricsRegistry().Meter(RevocationEnforcerDelete).Mark(int64(total)) + e.deleteMeter.Mark(int64(total)) } return nil diff --git a/controller/internal/policy/service_policy_enforcer.go b/controller/internal/policy/service_policy_enforcer.go index c01ff49ce..5b4596200 100644 --- a/controller/internal/policy/service_policy_enforcer.go +++ b/controller/internal/policy/service_policy_enforcer.go @@ -21,6 +21,7 @@ import ( "time" "github.com/michaelquigley/pfxlog" + "github.com/openziti/metrics" "github.com/openziti/ziti/v2/common/runner" "github.com/openziti/ziti/v2/controller/change" "github.com/openziti/ziti/v2/controller/db" @@ -38,15 +39,27 @@ const ( type ServicePolicyEnforcer struct { appEnv *env.AppEnv + // Resolved once and held. A Meter lookup takes a reference on every call and only Dispose releases + // one, so looking one up per run accumulates references and leaves the meter sampling after the + // registry is disposed. The timers are not reference counted, and are held here so the two read alike. + eventTimer metrics.Timer + eventDeleteMeter metrics.Meter + runTimer metrics.Timer + runDeleteMeter metrics.Meter *runner.BaseOperation notify chan struct{} } func NewServicePolicyEnforcer(appEnv *env.AppEnv, f time.Duration) *ServicePolicyEnforcer { + registry := appEnv.GetMetricsRegistry() result := &ServicePolicyEnforcer{ - appEnv: appEnv, - BaseOperation: runner.NewBaseOperation("ServicePolicyEnforcer", f), - notify: make(chan struct{}, 1), + appEnv: appEnv, + eventTimer: registry.Timer(SessionPolicyEnforcerEvent), + eventDeleteMeter: registry.Meter(SessionPolicyEnforcerEventDeletes), + runTimer: registry.Timer(SessionPolicyEnforcerRun), + runDeleteMeter: registry.Meter(SessionPolicyEnforcerRunDeletes), + BaseOperation: runner.NewBaseOperation("ServicePolicyEnforcer", f), + notify: make(chan struct{}, 1), } result.notify <- struct{}{} // ensure we do a full scan on startup db.ServiceEvents.AddServiceEventHandler(result.handleServiceEvent) @@ -70,7 +83,7 @@ func (enforcer *ServicePolicyEnforcer) handleServiceEvent(event *db.ServiceEvent startTime := time.Now() defer func() { - enforcer.appEnv.GetMetricsRegistry().Timer(SessionPolicyEnforcerEvent).UpdateSince(startTime) + enforcer.eventTimer.UpdateSince(startTime) }() log := pfxlog.Logger().WithField("event", event.String()) @@ -109,7 +122,7 @@ func (enforcer *ServicePolicyEnforcer) handleServiceEvent(event *db.ServiceEvent log.Debugf("session %v deleted", sessionId) } - enforcer.appEnv.GetMetricsRegistry().Meter(SessionPolicyEnforcerEventDeletes).Mark(int64(len(sessionsToDelete))) + enforcer.eventDeleteMeter.Mark(int64(len(sessionsToDelete))) } func (enforcer *ServicePolicyEnforcer) Run() error { @@ -123,7 +136,7 @@ func (enforcer *ServicePolicyEnforcer) Run() error { startTime := time.Now() defer func() { - enforcer.appEnv.GetMetricsRegistry().Timer(SessionPolicyEnforcerRun).UpdateSince(startTime) + enforcer.runTimer.UpdateSince(startTime) }() result, err := enforcer.appEnv.GetManagers().Session.Query("") @@ -174,7 +187,7 @@ func (enforcer *ServicePolicyEnforcer) Run() error { _ = enforcer.appEnv.GetManagers().Session.Delete(sessionId, ctx) } - enforcer.appEnv.GetMetricsRegistry().Meter(SessionPolicyEnforcerRunDeletes).Mark(int64(len(sessionsToRemove))) + enforcer.runDeleteMeter.Mark(int64(len(sessionsToRemove))) return nil } diff --git a/controller/internal/policy/session_enforcer_test.go b/controller/internal/policy/session_enforcer_test.go index 59eeb9be0..507e7ce2c 100644 --- a/controller/internal/policy/session_enforcer_test.go +++ b/controller/internal/policy/session_enforcer_test.go @@ -21,11 +21,11 @@ import ( "time" "github.com/google/go-cmp/cmp/cmpopts" - "github.com/openziti/ziti/v2/controller/storage/boltz" - "github.com/openziti/ziti/v2/controller/storage/boltztest" "github.com/openziti/ziti/v2/common/eid" "github.com/openziti/ziti/v2/controller/db" "github.com/openziti/ziti/v2/controller/model" + "github.com/openziti/ziti/v2/controller/storage/boltz" + "github.com/openziti/ziti/v2/controller/storage/boltztest" "github.com/sirupsen/logrus" ) @@ -71,9 +71,14 @@ func (ctx *enforcerTestContext) testSessionsCleanup() { boltztest.RequireReload(ctx, session) boltztest.RequireReload(ctx, session2) + // Built directly rather than through NewSessionEnforcer, which refuses a session timeout under a + // minute; the negative timeout here is what makes every session expired. The metrics still have to be + // supplied, since the enforcer holds them rather than resolving one per run. enforcer := &ApiSessionEnforcer{ appEnv: ctx, sessionTimeout: -time.Second, + runTimer: ctx.GetMetricsRegistry().Timer(ApiSessionEnforcerRun), + deleteMeter: ctx.GetMetricsRegistry().Meter(ApiSessionEnforcerDelete), } ctx.NoError(enforcer.Run())