From 7fbe60dda32406bc1ff9f72c10799d258ffc0b04 Mon Sep 17 00:00:00 2001 From: anantadwi13 Date: Fri, 14 Aug 2026 10:17:38 +0700 Subject: [PATCH 1/3] fix(treatment-service): remove nested RLock deadlock in project settings lookup findSubscribedProjectSettingsById held s.RLock() and, while still holding it, called findProjectSettingsById which took s.RLock() again on the same goroutine. Go's sync.RWMutex blocks new readers once a writer is queued (to avoid writer starvation), so if a writer (e.g. PollerService.Refresh -> Init, or a pubsub update handler) queued between the outer and nested RLock, the nested call blocked forever waiting for the writer, and the writer blocked forever waiting for the outer RLock to release -- a circular-wait deadlock. Extract the unlocked lookup into findProjectSettingsByIdLocked so callers that already hold the lock no longer re-lock. Co-Authored-By: Claude Sonnet 5 --- treatment-service/models/storage.go | 10 +- .../models/storage_deadlock_test.go | 130 ++++++++++++++++++ 2 files changed, 139 insertions(+), 1 deletion(-) create mode 100644 treatment-service/models/storage_deadlock_test.go diff --git a/treatment-service/models/storage.go b/treatment-service/models/storage.go index c94cf56..294421a 100644 --- a/treatment-service/models/storage.go +++ b/treatment-service/models/storage.go @@ -307,13 +307,21 @@ func (s *LocalStorage) findSubscribedProjectSettingsById(projectId ProjectId) *p return nil } - return s.findProjectSettingsById(projectId) + return s.findProjectSettingsByIdLocked(projectId) } func (s *LocalStorage) findProjectSettingsById(projectId ProjectId) *pubsub.ProjectSettings { s.RLock() defer s.RUnlock() + return s.findProjectSettingsByIdLocked(projectId) +} + +// findProjectSettingsByIdLocked assumes the caller already holds s's read (or write) lock. +// It must not itself call RLock/Lock, since sync.RWMutex blocks new readers once a writer is +// queued -- a nested RLock on the same goroutine that already holds the lock would deadlock +// against that queued writer. +func (s *LocalStorage) findProjectSettingsByIdLocked(projectId ProjectId) *pubsub.ProjectSettings { for _, settings := range s.ProjectSettings { if ProjectId(settings.ProjectId) == projectId { return settings diff --git a/treatment-service/models/storage_deadlock_test.go b/treatment-service/models/storage_deadlock_test.go new file mode 100644 index 0000000..21b6aad --- /dev/null +++ b/treatment-service/models/storage_deadlock_test.go @@ -0,0 +1,130 @@ +package models + +import ( + "sync" + "testing" + "time" + + _pubsub "github.com/caraml-dev/xp/common/pubsub" +) + +// TestFindSubscribedProjectSettingsById_NestedRLockDeadlocksWithPendingWriter reproduces the +// root cause suspected for the reported GetTreatmentForRequest deadlock: findSubscribedProjectSettingsById +// takes s.RLock() and then, while still holding it, calls findProjectSettingsById which takes +// s.RLock() again on the same goroutine. +// +// A recursive RLock is fine in isolation, but Go's sync.RWMutex blocks *new* readers once a +// writer is queued (to prevent writer starvation, see sync.RWMutex docs). So if a writer +// (e.g. PollerService.Refresh -> Init(), or a pubsub InsertExperiment/UpdateProjectSettings +// handler calling s.Lock()) queues up between the outer and the nested RLock, the nested RLock +// blocks forever waiting for the writer, and the writer blocks forever waiting for the outer +// RLock to be released (which never happens, since the function holding it is stuck in the +// nested call). That's a genuine circular-wait deadlock, not just contention. +// +// This test reproduces that interleaving deterministically: it manually holds the outer RLock +// (standing in for findSubscribedProjectSettingsById's lock), starts a writer that queues on +// s.Lock(), and then invokes the real findProjectSettingsById -- the exact call that is nested +// inside findSubscribedProjectSettingsById in production code. +func TestFindSubscribedProjectSettingsById_NestedRLockDeadlocksWithPendingWriter(t *testing.T) { + s := &LocalStorage{ + ProjectSettings: []*_pubsub.ProjectSettings{ + {ProjectId: 1}, + }, + } + + // Simulate findSubscribedProjectSettingsById's outer RLock, already held on this goroutine. + s.RLock() + + // Start a writer that mirrors PollerService.Refresh -> Init(), or a pubsub update handler. + // It queues on Lock() while the outer RLock above is held. + writerDone := make(chan struct{}) + go func() { + s.Lock() + s.Unlock() + close(writerDone) + }() + + // Give the writer time to actually queue behind the held RLock. This is inherently timing + // based, but the window only needs to be wide enough for the writer's Lock() call to enter + // its wait queue -- not for anything to complete -- so it is not flaky in practice. + time.Sleep(200 * time.Millisecond) + + // This is the exact nested call findSubscribedProjectSettingsById makes while still holding + // the outer RLock. With the writer now queued, this must block forever. + nestedRLockDone := make(chan *_pubsub.ProjectSettings, 1) + go func() { + nestedRLockDone <- s.findProjectSettingsById(1) + }() + + select { + case <-nestedRLockDone: + s.RUnlock() + t.Fatal("expected the nested RLock to deadlock while a writer was queued, but it completed instead; " + + "the suspected root cause did not reproduce") + case <-writerDone: + s.RUnlock() + t.Fatal("expected the writer to be blocked behind the still-held outer RLock, but it completed instead; " + + "the suspected root cause did not reproduce") + case <-time.After(2 * time.Second): + // Deadlock reproduced: neither the nested reader nor the queued writer could make + // progress. Root cause confirmed. + } + + // Release the outer RLock so the goroutines above (which are genuinely deadlocked in + // production) can unwind and this test doesn't leak them past its own completion. + s.RUnlock() + <-writerDone + <-nestedRLockDone +} + +// TestFindProjectSettingsWithId_ConcurrentWithWriter_NoDeadlock exercises the real production +// call graph (FindProjectSettingsWithId -> findSubscribedProjectSettingsById -> findProjectSettingsById) +// under concurrent read/write load, to prove the nested-RLock hazard is actually gone from that +// path (not just demonstrated in isolation). Many reader goroutines keep the nested-call path hot +// while a writer goroutine repeatedly takes s.Lock(), so if the nested RLock ever reappears, a +// writer will eventually queue between the outer and inner RLock calls on some reader goroutine +// and the whole test hangs past the timeout. +func TestFindProjectSettingsWithId_ConcurrentWithWriter_NoDeadlock(t *testing.T) { + projectId := ProjectId(1) + s := &LocalStorage{ + subscribedProjectIds: []ProjectId{projectId}, + ProjectSettings: []*_pubsub.ProjectSettings{{ProjectId: int64(projectId)}}, + } + + stop := make(chan struct{}) + var readers sync.WaitGroup + for i := 0; i < 50; i++ { + readers.Add(1) + go func() { + defer readers.Done() + for { + select { + case <-stop: + return + default: + s.FindProjectSettingsWithId(projectId) + } + } + }() + } + + writerDone := make(chan struct{}) + go func() { + defer close(writerDone) + for i := 0; i < 2000; i++ { + s.UpdateProjectSettings(&_pubsub.ProjectSettings{ProjectId: int64(projectId)}) + } + }() + + select { + case <-writerDone: + // Writer completed all its Lock/Unlock cycles without ever being stuck behind a + // reader that recursively RLocks -- no deadlock. + case <-time.After(5 * time.Second): + t.Fatal("deadlock detected: writer never completed while concurrent readers were calling " + + "FindProjectSettingsWithId, indicating a nested RLock on the read path") + } + + close(stop) + readers.Wait() +} From a0f2f0f7a7f77abb88785acc080774b8a43f900b Mon Sep 17 00:00:00 2001 From: anantadwi13 Date: Fri, 14 Aug 2026 14:34:05 +0700 Subject: [PATCH 2/3] feat(treatment-service): add feature-flagged call metrics on LocalStorage Adds a call counter and call-duration histogram around LocalStorage's public methods, gated behind a new Monitoring.LocalStorageMetricsEnabled config flag. A stuck method (e.g. a lock deadlock) shows up as its call counter climbing while its duration histogram's count stays frozen. Routes through the existing MetricService (LogRequestCount / LogLatencyHistogram) rather than a separate metrics backend, so this respects the existing Monitoring.Kind sink and reuses the same Prometheus registration path as every other treatment-service metric. Since services already imports models (for *LocalStorage), models can't import services back, so LocalStorage depends only on a small LocalStorageMetricsRecorder interface (satisfied by MetricService as-is); appcontext wires the two together after both are constructed. Co-Authored-By: Claude Sonnet 5 --- plugins/turing/runner/experiment_runner.go | 13 ++ treatment-service/appcontext/appcontext.go | 3 + treatment-service/config/config.go | 4 + .../instrumentation/prometheus.go | 31 +++++ treatment-service/models/storage.go | 76 ++++++++++- treatment-service/models/storage_metrics.go | 42 ++++++ .../models/storage_metrics_test.go | 123 ++++++++++++++++++ treatment-service/services/metric_service.go | 8 ++ .../services/metric_service_test.go | 16 +++ 9 files changed, 315 insertions(+), 1 deletion(-) create mode 100644 treatment-service/models/storage_metrics.go create mode 100644 treatment-service/models/storage_metrics_test.go diff --git a/plugins/turing/runner/experiment_runner.go b/plugins/turing/runner/experiment_runner.go index 12a39ba..c40d364 100644 --- a/plugins/turing/runner/experiment_runner.go +++ b/plugins/turing/runner/experiment_runner.go @@ -238,6 +238,19 @@ func (er *experimentRunner) RegisterMetricsCollector( instrumentation.AdditionalNoMatchingExperimentRequestCountLabels..., ), }, + { + Name: string(instrumentation.LocalStorageCallCount), + Type: routerMetrics.CounterMetricType, + Description: instrumentation.LocalStorageCallCountHelpString, + Labels: instrumentation.LocalStorageMethodLabels, + }, + { + Name: string(instrumentation.LocalStorageCallDurationMs), + Type: routerMetrics.HistogramMetricType, + Description: instrumentation.LocalStorageCallDurationMsHelpString, + Buckets: instrumentation.RequestLatencyBuckets, + Labels: instrumentation.LocalStorageMethodLabels, + }, }) if err != nil { return err diff --git a/treatment-service/appcontext/appcontext.go b/treatment-service/appcontext/appcontext.go index d574aa7..a4bacaa 100644 --- a/treatment-service/appcontext/appcontext.go +++ b/treatment-service/appcontext/appcontext.go @@ -67,6 +67,9 @@ func NewAppContext(cfg *config.Config) (*AppContext, error) { if err != nil { return nil, err } + if cfg.MonitoringConfig.LocalStorageMetricsEnabled { + localStorage.SetMetricsRecorder(metricService) + } log.Println("Initializing assigned treatment logger...") loggerConfig := cfg.AssignedTreatmentLogger diff --git a/treatment-service/config/config.go b/treatment-service/config/config.go index d2c1d5f..48d3200 100644 --- a/treatment-service/config/config.go +++ b/treatment-service/config/config.go @@ -87,6 +87,10 @@ const ( type Monitoring struct { Kind MetricSinkKind `json:"kind" default:"" validate:"required"` MetricLabels []string `json:"metric_labels" default:""` + // LocalStorageMetricsEnabled toggles per-method call counter and call duration + // histogram instrumentation on models.LocalStorage's public methods. Independent of + // Kind, since it self-registers directly against the default Prometheus registry. + LocalStorageMetricsEnabled bool `json:"local_storage_metrics_enabled" default:"false"` } type ManagementServiceConfig struct { diff --git a/treatment-service/instrumentation/prometheus.go b/treatment-service/instrumentation/prometheus.go index f4b74b6..8512c71 100644 --- a/treatment-service/instrumentation/prometheus.go +++ b/treatment-service/instrumentation/prometheus.go @@ -26,6 +26,14 @@ const ( FetchTreatmentRequestCountHelpString string = "Counter for no. of Fetch Treatment requests with matching experiments" // NoMatchingExperimentRequestCountHelpString is the help string of the NoMatchingExperimentRequestCount metric NoMatchingExperimentRequestCountHelpString string = "Counter for no. of Fetch Treatment requests with no matching experiments" + // LocalStorageCallCount is the key to measure calls to LocalStorage's public methods + LocalStorageCallCount metrics.MetricName = "local_storage_calls_total" + // LocalStorageCallDurationMs is the key to measure how long a call to a LocalStorage public method took + LocalStorageCallDurationMs metrics.MetricName = "local_storage_call_duration_ms" + // LocalStorageCallCountHelpString is the help string of the LocalStorageCallCount metric + LocalStorageCallCountHelpString string = "Counter for calls to LocalStorage's public methods, incremented on entry" + // LocalStorageCallDurationMsHelpString is the help string of the LocalStorageCallDurationMs metric + LocalStorageCallDurationMsHelpString string = "Histogram for how long (in milliseconds) a call to a LocalStorage public method took to return" ) // RequestLatencyBuckets defines the buckets used in the custom Histogram metrics @@ -49,6 +57,12 @@ var FetchTreatmentRequestDurationMsLabels = []string{"project_name", "experiment // ExperimentLookupDurationMsLabels defines additional labels needed for the ExperimentLookupDurationMs histogram map var ExperimentLookupDurationMsLabels = []string{"project_name"} +// LocalStorageMethodLabels defines the labels needed for the LocalStorageCallCount counter map and the +// LocalStorageCallDurationMs histogram map. Deliberately not combined with the caller-supplied custom +// MetricLabels (cfg.MetricLabels) used elsewhere in this file -- LocalStorage calls aren't tied to a project +// or experiment, just a method name. +var LocalStorageMethodLabels = []string{"method"} + var GaugeMap = map[metrics.MetricName]metrics.PrometheusGaugeVec{} func GetCounterMap(labels []string) map[metrics.MetricName]metrics.PrometheusCounterVec { @@ -76,6 +90,14 @@ func GetCounterMap(labels []string) map[metrics.MetricName]metrics.PrometheusCou }, noMatchingExperimentlabels, ), + LocalStorageCallCount: prometheus.NewCounterVec(prometheus.CounterOpts{ + Namespace: Namespace, + Subsystem: Subsystem, + Help: LocalStorageCallCountHelpString, + Name: string(LocalStorageCallCount), + }, + LocalStorageMethodLabels, + ), } return counterMap @@ -102,6 +124,15 @@ func GetHistogramMap() map[metrics.MetricName]metrics.PrometheusHistogramVec { }, ExperimentLookupDurationMsLabels, ), + LocalStorageCallDurationMs: prometheus.NewHistogramVec(prometheus.HistogramOpts{ + Namespace: Namespace, + Subsystem: Subsystem, + Name: string(LocalStorageCallDurationMs), + Help: LocalStorageCallDurationMsHelpString, + Buckets: RequestLatencyBuckets, + }, + LocalStorageMethodLabels, + ), } return histogramMap diff --git a/treatment-service/models/storage.go b/treatment-service/models/storage.go index 294421a..dcb6af2 100644 --- a/treatment-service/models/storage.go +++ b/treatment-service/models/storage.go @@ -59,6 +59,28 @@ type LocalStorage struct { subscribedProjectIds []ProjectId Segmenters map[string]schema.SegmenterType ProjectSegmenters map[ProjectId]map[string]schema.SegmenterType + // metricsRecorder is nil until SetMetricsRecorder is called; instrumented methods treat a + // nil recorder as "metrics disabled" and skip reporting entirely. In production this is a + // services.MetricService (wired in appcontext.NewAppContext, after both are constructed -- + // models can't import services directly, since services already imports models). + // + // Every instrumented public method here calls into metricsRecorder.LogRequestCount / + // LogLatencyHistogram via instrumentCall. services.MetricService itself already calls back + // into this struct: GetLabels and GetProjectNameLabel both call FindProjectSettingsWithId, + // which is one of the instrumented methods. That's fine today because LogRequestCount and + // LogLatencyHistogram are pure leaves -- they only reach the external metrics collector and + // never call back into GetLabels, GetProjectNameLabel, or any LocalStorage method. If you + // ever change what a recorder's LogRequestCount/LogLatencyHistogram does, make sure it still + // can't reach back into an instrumented LocalStorage method (directly or transitively) -- + // that would turn this into unbounded recursion, not just a slow call. + metricsRecorder LocalStorageMetricsRecorder +} + +// SetMetricsRecorder wires recorder into LocalStorage's public methods, which will start +// reporting a call counter and call duration histogram to it. Call once, after construction; +// leaving it unset (the default) means no metrics are reported. +func (s *LocalStorage) SetMetricsRecorder(recorder LocalStorageMetricsRecorder) { + s.metricsRecorder = recorder } type Match struct { @@ -254,6 +276,10 @@ func (i *ExperimentIndex) checkSegmentHasWeakMatch(segmentName string) bool { } func (s *LocalStorage) InsertProjectSettings(projectSettings *pubsub.ProjectSettings) error { + if s.metricsRecorder != nil { + defer s.instrumentCall("InsertProjectSettings")() + } + // check that settings with the same Id doesn't exist existingProjectSettings := s.findProjectSettingsById(ProjectId(projectSettings.GetProjectId())) if existingProjectSettings != nil { @@ -274,6 +300,10 @@ func (s *LocalStorage) InsertProjectSettings(projectSettings *pubsub.ProjectSett } func (s *LocalStorage) UpdateProjectSettings(updatedProjectSettings *pubsub.ProjectSettings) { + if s.metricsRecorder != nil { + defer s.instrumentCall("UpdateProjectSettings")() + } + s.Lock() defer s.Unlock() @@ -285,6 +315,10 @@ func (s *LocalStorage) UpdateProjectSettings(updatedProjectSettings *pubsub.Proj } func (s *LocalStorage) FindProjectSettingsWithId(projectId ProjectId) *pubsub.ProjectSettings { + if s.metricsRecorder != nil { + defer s.instrumentCall("FindProjectSettingsWithId")() + } + projectSettings := s.findSubscribedProjectSettingsById(projectId) if projectSettings != nil { return projectSettings @@ -345,6 +379,10 @@ func (s *LocalStorage) fetchProjectSettingsWithId(projectId ProjectId) (*pubsub. } func (s *LocalStorage) GetSegmentersTypeMapping(projectId ProjectId) (map[string]schema.SegmenterType, error) { + if s.metricsRecorder != nil { + defer s.instrumentCall("GetSegmentersTypeMapping")() + } + s.RLock() defer s.RUnlock() @@ -356,6 +394,10 @@ func (s *LocalStorage) GetSegmentersTypeMapping(projectId ProjectId) (map[string } func (s *LocalStorage) FindExperiments(projectId ProjectId, filters []SegmentFilter) []*ExperimentMatch { + if s.metricsRecorder != nil { + defer s.instrumentCall("FindExperiments")() + } + s.RLock() defer s.RUnlock() @@ -390,6 +432,10 @@ func (s *LocalStorage) FindExperiments(projectId ProjectId, filters []SegmentFil } func (s *LocalStorage) FindExperimentWithId(projectId ProjectId, experimentId int64) *pubsub.Experiment { + if s.metricsRecorder != nil { + defer s.instrumentCall("FindExperimentWithId")() + } + s.RLock() defer s.RUnlock() @@ -462,6 +508,10 @@ func NewExperimentIndex(experiment *pubsub.Experiment) *ExperimentIndex { } func (s *LocalStorage) InsertExperiment(experiment *pubsub.Experiment) { + if s.metricsRecorder != nil { + defer s.instrumentCall("InsertExperiment")() + } + projectId := ProjectId(experiment.ProjectId) s.Lock() defer s.Unlock() @@ -483,6 +533,10 @@ func (s *LocalStorage) InsertExperiment(experiment *pubsub.Experiment) { } func (s *LocalStorage) UpdateExperiment(experiment *pubsub.Experiment) { + if s.metricsRecorder != nil { + defer s.instrumentCall("UpdateExperiment")() + } + projectId := ProjectId(experiment.ProjectId) s.Lock() defer s.Unlock() @@ -510,6 +564,10 @@ func (s *LocalStorage) UpdateExperiment(experiment *pubsub.Experiment) { // DumpExperiments is used to dump the experiment from the local cache into the // given file, as JSON. Useful for debugging. func (s *LocalStorage) DumpExperiments(filepath string) error { + if s.metricsRecorder != nil { + defer s.instrumentCall("DumpExperiments")() + } + s.RLock() defer s.RUnlock() @@ -521,6 +579,10 @@ func (s *LocalStorage) DumpExperiments(filepath string) error { } func (s *LocalStorage) Init() error { + if s.metricsRecorder != nil { + defer s.instrumentCall("Init")() + } + var subscribedProjectSettings []*pubsub.ProjectSettings var err error if len(s.subscribedProjectIds) > 0 { @@ -629,7 +691,11 @@ func NewLocalStorage( return nil, err } segmenterCache := make(map[ProjectId]map[string]schema.SegmenterType) - s := LocalStorage{managementClient: xpClient, subscribedProjectIds: projectIds, ProjectSegmenters: segmenterCache} + s := LocalStorage{ + managementClient: xpClient, + subscribedProjectIds: projectIds, + ProjectSegmenters: segmenterCache, + } err = s.Init() return &s, err @@ -717,12 +783,20 @@ func (s *LocalStorage) fetchProjectSegmenters(settings []*pubsub.ProjectSettings } func (s *LocalStorage) UpdateProjectSegmenters(segmenter *_segmenters.SegmenterConfiguration, projectId int64) { + if s.metricsRecorder != nil { + defer s.instrumentCall("UpdateProjectSegmenters")() + } + s.Lock() defer s.Unlock() s.ProjectSegmenters[ProjectId(projectId)][segmenter.Name] = schema.SegmenterType(strings.ToLower(segmenter.Type.String())) } func (s *LocalStorage) DeleteProjectSegmenters(segmenterName string, projectId int64) { + if s.metricsRecorder != nil { + defer s.instrumentCall("DeleteProjectSegmenters")() + } + s.Lock() defer s.Unlock() delete(s.ProjectSegmenters[ProjectId(projectId)], segmenterName) diff --git a/treatment-service/models/storage_metrics.go b/treatment-service/models/storage_metrics.go new file mode 100644 index 0000000..12839cb --- /dev/null +++ b/treatment-service/models/storage_metrics.go @@ -0,0 +1,42 @@ +package models + +import ( + "time" + + "github.com/caraml-dev/mlp/api/pkg/instrumentation/metrics" + "github.com/caraml-dev/xp/treatment-service/instrumentation" +) + +// LocalStorageMetricsRecorder is implemented by whatever wants to observe calls to +// LocalStorage's public methods. It's deliberately just services.MetricService's existing +// LogRequestCount/LogLatencyHistogram methods, rather than bespoke ones -- a MetricService +// satisfies this as-is. models has no import on services (which itself imports models for +// *LocalStorage, e.g. in NewMetricService), so appcontext wires the two together after both +// are constructed, via SetMetricsRecorder. +type LocalStorageMetricsRecorder interface { + LogRequestCount(labels map[string]string, loggingMetric metrics.MetricName) + LogLatencyHistogram(begin time.Time, labels map[string]string, loggingMetric metrics.MetricName) +} + +// instrumentCall reports a call to method via s.metricsRecorder (a no-op if none is set) and +// returns a func that reports the call's duration; callers defer the returned func +// immediately, e.g.: +// +// func (s *LocalStorage) Foo(...) ... { +// if s.metricsRecorder != nil { +// defer s.instrumentCall("Foo")() +// } +// ... +// } +func (s *LocalStorage) instrumentCall(method string) func() { + if s.metricsRecorder == nil { + return func() {} + } + + labels := map[string]string{"method": method} + s.metricsRecorder.LogRequestCount(labels, instrumentation.LocalStorageCallCount) + begin := time.Now() + return func() { + s.metricsRecorder.LogLatencyHistogram(begin, labels, instrumentation.LocalStorageCallDurationMs) + } +} diff --git a/treatment-service/models/storage_metrics_test.go b/treatment-service/models/storage_metrics_test.go new file mode 100644 index 0000000..7541f00 --- /dev/null +++ b/treatment-service/models/storage_metrics_test.go @@ -0,0 +1,123 @@ +package models + +import ( + "testing" + "time" + + "github.com/caraml-dev/mlp/api/pkg/instrumentation/metrics" + "github.com/stretchr/testify/require" + "google.golang.org/protobuf/types/known/timestamppb" + + _pubsub "github.com/caraml-dev/xp/common/pubsub" + "github.com/caraml-dev/xp/treatment-service/instrumentation" +) + +// fakeMetricsRecorder is a test double for LocalStorageMetricsRecorder (i.e. for +// services.MetricService's LogRequestCount/LogLatencyHistogram), recording every call it +// receives so tests can assert on ordering and arguments without depending on any real +// metrics backend (Prometheus, RPC, ...). +type fakeMetricsRecorder struct { + callCounts map[string]int + durationCounts map[string]int +} + +func newFakeMetricsRecorder() *fakeMetricsRecorder { + return &fakeMetricsRecorder{ + callCounts: map[string]int{}, + durationCounts: map[string]int{}, + } +} + +func (f *fakeMetricsRecorder) LogRequestCount(labels map[string]string, loggingMetric metrics.MetricName) { + if loggingMetric != instrumentation.LocalStorageCallCount { + return + } + f.callCounts[labels["method"]]++ +} + +func (f *fakeMetricsRecorder) LogLatencyHistogram(begin time.Time, labels map[string]string, loggingMetric metrics.MetricName) { + if loggingMetric != instrumentation.LocalStorageCallDurationMs { + return + } + f.durationCounts[labels["method"]]++ +} + +// TestInstrumentCall verifies the shared helper's contract directly: the counter reports +// immediately when instrumentCall is invoked, and the duration only reports once the returned +// func is actually called (mirroring how it's used: called immediately, deferred return value). +func TestInstrumentCall(t *testing.T) { + recorder := newFakeMetricsRecorder() + s := &LocalStorage{} + s.SetMetricsRecorder(recorder) + + done := s.instrumentCall("TestMethod") + require.Equal(t, 1, recorder.callCounts["TestMethod"], "call count should report immediately") + require.Equal(t, 0, recorder.durationCounts["TestMethod"], "duration should not report until done() runs") + + done() + require.Equal(t, 1, recorder.durationCounts["TestMethod"], "duration should report once done() runs") +} + +// TestInstrumentCall_NoRecorder verifies that with no recorder set (the default), instrumentCall +// returns a harmless no-op -- this is what every public method relies on to skip metrics +// entirely when nothing has called SetMetricsRecorder. +func TestInstrumentCall_NoRecorder(t *testing.T) { + s := &LocalStorage{} + done := s.instrumentCall("TestMethod") + require.NotPanics(t, done) +} + +// TestFindExperiments_MetricsGatedByRecorder exercises a real read-path public method end to +// end: with no recorder set (matching every existing caller/test), nothing is reported; once +// SetMetricsRecorder is called, the call is counted and its duration reported. +func TestFindExperiments_MetricsGatedByRecorder(t *testing.T) { + method := "FindExperiments" + + t.Run("no recorder by default", func(t *testing.T) { + s := &LocalStorage{Experiments: map[ProjectId][]*ExperimentIndex{}} + s.FindExperiments(0, nil) + // No recorder set -- nothing to assert beyond "this didn't panic". + }) + + t.Run("recorder set", func(t *testing.T) { + recorder := newFakeMetricsRecorder() + s := &LocalStorage{Experiments: map[ProjectId][]*ExperimentIndex{}} + s.SetMetricsRecorder(recorder) + + s.FindExperiments(0, nil) + + require.Equal(t, 1, recorder.callCounts[method]) + require.Equal(t, 1, recorder.durationCounts[method]) + }) +} + +// TestInsertExperiment_MetricsGatedByRecorder mirrors the above for a write-path public +// method, to confirm the same pattern applies there too. +func TestInsertExperiment_MetricsGatedByRecorder(t *testing.T) { + method := "InsertExperiment" + newExperiment := func() *_pubsub.Experiment { + return &_pubsub.Experiment{ + Id: 1, + ProjectId: 1, + Status: _pubsub.Experiment_Active, + StartTime: timestamppb.New(time.Now()), + EndTime: timestamppb.New(time.Now().Add(time.Hour)), + } + } + + t.Run("no recorder by default", func(t *testing.T) { + s := &LocalStorage{Experiments: map[ProjectId][]*ExperimentIndex{}} + s.InsertExperiment(newExperiment()) + }) + + t.Run("recorder set", func(t *testing.T) { + recorder := newFakeMetricsRecorder() + s := &LocalStorage{Experiments: map[ProjectId][]*ExperimentIndex{}} + s.SetMetricsRecorder(recorder) + + s.InsertExperiment(newExperiment()) + + require.Equal(t, 1, recorder.callCounts[method]) + require.Equal(t, 1, recorder.durationCounts[method]) + }) +} diff --git a/treatment-service/services/metric_service.go b/treatment-service/services/metric_service.go index 9b291c6..11bf75c 100644 --- a/treatment-service/services/metric_service.go +++ b/treatment-service/services/metric_service.go @@ -81,6 +81,10 @@ func (ms *metricService) LogLatencyHistogram(begin time.Time, labels map[string] err = metrics.Glob().MeasureDurationMsSince( instrumentation.ExperimentLookupDurationMs, begin, labels, ) + case instrumentation.LocalStorageCallDurationMs: + err = metrics.Glob().MeasureDurationMsSince( + instrumentation.LocalStorageCallDurationMs, begin, labels, + ) } if err != nil { log.Printf("error while logging %s metrics (latency): %s", loggingMetric, err) @@ -102,6 +106,10 @@ func (ms *metricService) LogRequestCount(labels map[string]string, loggingMetric err = metrics.Glob().Inc( instrumentation.NoMatchingExperimentRequestCount, labels, ) + case instrumentation.LocalStorageCallCount: + err = metrics.Glob().Inc( + instrumentation.LocalStorageCallCount, labels, + ) } if err != nil { log.Printf("error while logging metrics (request_count): %s", err) diff --git a/treatment-service/services/metric_service_test.go b/treatment-service/services/metric_service_test.go index b3d7596..7de4747 100644 --- a/treatment-service/services/metric_service_test.go +++ b/treatment-service/services/metric_service_test.go @@ -176,3 +176,19 @@ func (s *MetricServiceTestSuite) TestLogRequestCount() { expectedErrorStdOut := "error while logging metrics (request_count)" s.Suite.Require().Contains(stdout, expectedErrorStdOut) } + +func (s *MetricServiceTestSuite) TestLogLocalStorageCallCount() { + stdout := testutils.CaptureStderrLogs(func() { + s.MetricService.LogRequestCount(map[string]string{"method": "FindExperiments"}, instrumentation.LocalStorageCallCount) + }) + s.Suite.Require().Equal("", stdout) +} + +func (s *MetricServiceTestSuite) TestLogLocalStorageCallDuration() { + stdout := testutils.CaptureStderrLogs(func() { + s.MetricService.LogLatencyHistogram( + time.Now(), map[string]string{"method": "FindExperiments"}, instrumentation.LocalStorageCallDurationMs, + ) + }) + s.Suite.Require().Equal("", stdout) +} From afafec029c355cfb13f124ace5b74f6b74494bd7 Mon Sep 17 00:00:00 2001 From: anantadwi13 Date: Fri, 14 Aug 2026 17:54:07 +0700 Subject: [PATCH 3/3] fix(treatment-service): suppress SA2001 false positive in deadlock test The simulated writer goroutine's Lock()/Unlock() pair is deliberately empty -- acquiring and releasing the lock is the observable event under test, not protection of shared state -- but staticcheck flags it as an empty critical section, failing CI lint. Co-Authored-By: Claude Sonnet 5 --- treatment-service/models/storage_deadlock_test.go | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/treatment-service/models/storage_deadlock_test.go b/treatment-service/models/storage_deadlock_test.go index 21b6aad..cc5ece2 100644 --- a/treatment-service/models/storage_deadlock_test.go +++ b/treatment-service/models/storage_deadlock_test.go @@ -39,8 +39,11 @@ func TestFindSubscribedProjectSettingsById_NestedRLockDeadlocksWithPendingWriter // It queues on Lock() while the outer RLock above is held. writerDone := make(chan struct{}) go func() { - s.Lock() - s.Unlock() + // SA2001: critical section is deliberately empty -- acquiring and releasing the lock is + // the observable event under test (proof the writer can make progress), not a means to + // protect shared state. + s.Lock() //nolint:staticcheck + s.Unlock() //nolint:staticcheck close(writerDone) }()