posthog-go icon indicating copy to clipboard operation
posthog-go copied to clipboard
verified publisher icon PostHog

Data races with feature flag poller

Open zaynetro opened this issue 2 years ago • 3 comments

SDK with feature flag poller enabled has data races:

go test -race -v .

There seem two be a couple of offenders:

  1. poller.fetchedFlagsSuccessfullyOnce (this and this)
  2. poller.featureFlags and everywhere where they are read with poller.GetFeatureFlags()

Full log: test.log

zaynetro avatar Feb 02 '24 14:02 zaynetro

We were running into this as well, and it appears fixed by #38 (merged as commit 87b23fe). Upgrading to v0.0.0-20240327112532-87b23fe11103 removed the data race from our logs. Thanks for the fix! This can probably be closed now.

lukfugl avatar Apr 16 '24 19:04 lukfugl

indeed, thanks!

neilkakkar avatar Apr 17 '24 09:04 neilkakkar

This is not fully fixed. Here is an example:

package main

import (
	"sync"
	"testing"
	"time"

	"github.com/posthog/posthog-go"
)

var pollInterval = 2 * time.Second

func nextTick() time.Duration {
	now := time.Now()
	elapsed := time.Duration(now.Minute()*60+now.Second()) * time.Second
	remaining := pollInterval - elapsed%pollInterval
	return remaining.Abs()
}

func TestRaces(t *testing.T) {
	client, err := posthog.NewWithConfig("<set your API key>", posthog.Config{
		PersonalApiKey: "<set your personal API key>",
		Verbose:        true,

		NextFeatureFlagsPollingTick: nextTick,
	})
	if err != nil {
		t.Fatal(err)
	}

	var wg sync.WaitGroup
	for i := 0; i < 2; i += 1 {
		wg.Add(1)
		go func() {
			defer wg.Done()

			timer := time.NewTimer(nextTick())
			defer timer.Stop()
			<-timer.C

			client.IsFeatureEnabled(posthog.FeatureFlagPayload{
				Key:        "hello",
				DistinctId: "my-user",
			})
		}()
	}
	wg.Wait()

	<-time.After(6 * time.Second)
}
Test log 
> go test -race cmd/roman/roman_test.go
==================
WARNING: DATA RACE
Read at 0x00c000125128 by goroutine 10:
  github.com/posthog/posthog-go.(*FeatureFlagsPoller).GetFeatureFlags()
      /Users/roman/Code/trial/posthog-go/featureflags.go:815 +0x68
  github.com/posthog/posthog-go.(*FeatureFlagsPoller).GetFeatureFlag()
      /Users/roman/Code/trial/posthog-go/featureflags.go:204 +0x54
  github.com/posthog/posthog-go.(*client).GetFeatureFlag()
      /Users/roman/Code/trial/posthog-go/posthog.go:286 +0x10c
  github.com/posthog/posthog-go.(*client).IsFeatureEnabled()
      /Users/roman/Code/trial/posthog-go/posthog.go:252 +0xc0
  command-line-arguments.TestRaces.func1()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:41 +0x18c

Previous write at 0x00c000125128 by goroutine 8:
  github.com/posthog/posthog-go.(*FeatureFlagsPoller).fetchNewFeatureFlags()
      /Users/roman/Code/trial/posthog-go/featureflags.go:195 +0x550
  github.com/posthog/posthog-go.(*FeatureFlagsPoller).run()
      /Users/roman/Code/trial/posthog-go/featureflags.go:166 +0x154
  github.com/posthog/posthog-go.newFeatureFlagsPoller.gowrap1()
      /Users/roman/Code/trial/posthog-go/featureflags.go:146 +0x34

Goroutine 10 (running) created at:
  command-line-arguments.TestRaces()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:34 +0x124
  testing.tRunner()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1689 +0x180
  testing.(*T).Run.gowrap1()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1742 +0x40

Goroutine 8 (running) created at:
  github.com/posthog/posthog-go.newFeatureFlagsPoller()
      /Users/roman/Code/trial/posthog-go/featureflags.go:146 +0x22c
  github.com/posthog/posthog-go.NewWithConfig()
      /Users/roman/Code/trial/posthog-go/posthog.go:114 +0x628
  command-line-arguments.TestRaces()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:21 +0x90
  testing.tRunner()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1689 +0x180
  testing.(*T).Run.gowrap1()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1742 +0x40
==================
==================
WARNING: DATA RACE
Read at 0x00c000125140 by goroutine 11:
  github.com/posthog/posthog-go.(*FeatureFlagsPoller).GetFeatureFlag()
      /Users/roman/Code/trial/posthog-go/featureflags.go:208 +0x78
  github.com/posthog/posthog-go.(*client).GetFeatureFlag()
      /Users/roman/Code/trial/posthog-go/posthog.go:286 +0x10c
  github.com/posthog/posthog-go.(*client).IsFeatureEnabled()
      /Users/roman/Code/trial/posthog-go/posthog.go:252 +0xc0
  command-line-arguments.TestRaces.func1()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:41 +0x18c

Previous write at 0x00c000125140 by goroutine 8:
  github.com/posthog/posthog-go.(*FeatureFlagsPoller).fetchNewFeatureFlags()
      /Users/roman/Code/trial/posthog-go/featureflags.go:196 +0x5b8
  github.com/posthog/posthog-go.(*FeatureFlagsPoller).run()
      /Users/roman/Code/trial/posthog-go/featureflags.go:166 +0x154
  github.com/posthog/posthog-go.newFeatureFlagsPoller.gowrap1()
      /Users/roman/Code/trial/posthog-go/featureflags.go:146 +0x34

Goroutine 11 (running) created at:
  command-line-arguments.TestRaces()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:34 +0x124
  testing.tRunner()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1689 +0x180
  testing.(*T).Run.gowrap1()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1742 +0x40

Goroutine 8 (running) created at:
  github.com/posthog/posthog-go.newFeatureFlagsPoller()
      /Users/roman/Code/trial/posthog-go/featureflags.go:146 +0x22c
  github.com/posthog/posthog-go.NewWithConfig()
      /Users/roman/Code/trial/posthog-go/posthog.go:114 +0x628
  command-line-arguments.TestRaces()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:21 +0x90
  testing.tRunner()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1689 +0x180
  testing.(*T).Run.gowrap1()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1742 +0x40
==================
==================
WARNING: DATA RACE
Read at 0x00c0001fec60 by goroutine 10:
  github.com/posthog/posthog-go.(*FeatureFlagsPoller).GetFeatureFlag()
      /Users/roman/Code/trial/posthog-go/featureflags.go:213 +0x110
  github.com/posthog/posthog-go.(*client).GetFeatureFlag()
      /Users/roman/Code/trial/posthog-go/posthog.go:286 +0x10c
  github.com/posthog/posthog-go.(*client).IsFeatureEnabled()
      /Users/roman/Code/trial/posthog-go/posthog.go:252 +0xc0
  command-line-arguments.TestRaces.func1()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:41 +0x18c

Previous write at 0x00c0001fec60 by goroutine 8:
  runtime.slicecopy()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/runtime/slice.go:325 +0x0
  github.com/posthog/posthog-go.(*FeatureFlagsPoller).fetchNewFeatureFlags()
      /Users/roman/Code/trial/posthog-go/featureflags.go:193 +0x534
  github.com/posthog/posthog-go.(*FeatureFlagsPoller).run()
      /Users/roman/Code/trial/posthog-go/featureflags.go:166 +0x154
  github.com/posthog/posthog-go.newFeatureFlagsPoller.gowrap1()
      /Users/roman/Code/trial/posthog-go/featureflags.go:146 +0x34

Goroutine 10 (running) created at:
  command-line-arguments.TestRaces()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:34 +0x124
  testing.tRunner()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1689 +0x180
  testing.(*T).Run.gowrap1()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1742 +0x40

Goroutine 8 (running) created at:
  github.com/posthog/posthog-go.newFeatureFlagsPoller()
      /Users/roman/Code/trial/posthog-go/featureflags.go:146 +0x22c
  github.com/posthog/posthog-go.NewWithConfig()
      /Users/roman/Code/trial/posthog-go/posthog.go:114 +0x628
  command-line-arguments.TestRaces()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:21 +0x90
  testing.tRunner()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1689 +0x180
  testing.(*T).Run.gowrap1()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1742 +0x40
==================
posthog 2024/04/17 16:09:54 INFO: buffer (0/250) {capture posthog-go 1.0.0 2024-04-17 16:09:54.958869 +0300 EEST m=+2.150707501 my-user $feature_flag_called map[$feature_flag:hello $feature_flag_errored:false $feature_flag_response:false $groups:map[] $lib:posthog-go $lib_version:1.0.0] false}
==================
WARNING: DATA RACE
Read at 0x00c000122de0 by goroutine 10:
  runtime.mapaccess1_faststr()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/runtime/map_faststr.go:13 +0x40c
  github.com/posthog/posthog-go.(*SizeLimitedMap).contains()
      /Users/roman/Code/trial/posthog-go/util.go:31 +0x1a0
  github.com/posthog/posthog-go.(*client).GetFeatureFlag()
      /Users/roman/Code/trial/posthog-go/posthog.go:287 +0x120
  github.com/posthog/posthog-go.(*client).IsFeatureEnabled()
      /Users/roman/Code/trial/posthog-go/posthog.go:252 +0xc0
  command-line-arguments.TestRaces.func1()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:41 +0x18c

Previous write at 0x00c000122de0 by goroutine 11:
  runtime.mapaccess2_faststr()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/runtime/map_faststr.go:108 +0x42c
  github.com/posthog/posthog-go.(*SizeLimitedMap).add()
      /Users/roman/Code/trial/posthog-go/util.go:26 +0x704
  github.com/posthog/posthog-go.(*client).GetFeatureFlag()
      /Users/roman/Code/trial/posthog-go/posthog.go:297 +0x488
  github.com/posthog/posthog-go.(*client).IsFeatureEnabled()
      /Users/roman/Code/trial/posthog-go/posthog.go:252 +0xc0
  command-line-arguments.TestRaces.func1()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:41 +0x18c

Goroutine 10 (running) created at:
  command-line-arguments.TestRaces()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:34 +0x124
  testing.tRunner()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1689 +0x180
  testing.(*T).Run.gowrap1()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1742 +0x40

Goroutine 11 (finished) created at:
  command-line-arguments.TestRaces()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:34 +0x124
  testing.tRunner()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1689 +0x180
  testing.(*T).Run.gowrap1()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1742 +0x40
==================
==================
WARNING: DATA RACE
Read at 0x00c0000b2348 by goroutine 10:
  github.com/posthog/posthog-go.(*SizeLimitedMap).contains()
      /Users/roman/Code/trial/posthog-go/util.go:31 +0x1ac
  github.com/posthog/posthog-go.(*client).GetFeatureFlag()
      /Users/roman/Code/trial/posthog-go/posthog.go:287 +0x120
  github.com/posthog/posthog-go.(*client).IsFeatureEnabled()
      /Users/roman/Code/trial/posthog-go/posthog.go:252 +0xc0
  command-line-arguments.TestRaces.func1()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:41 +0x18c

Previous write at 0x00c0000b2348 by goroutine 11:
  github.com/posthog/posthog-go.(*SizeLimitedMap).add()
      /Users/roman/Code/trial/posthog-go/util.go:26 +0x710
  github.com/posthog/posthog-go.(*client).GetFeatureFlag()
      /Users/roman/Code/trial/posthog-go/posthog.go:297 +0x488
  github.com/posthog/posthog-go.(*client).IsFeatureEnabled()
      /Users/roman/Code/trial/posthog-go/posthog.go:252 +0xc0
  command-line-arguments.TestRaces.func1()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:41 +0x18c

Goroutine 10 (running) created at:
  command-line-arguments.TestRaces()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:34 +0x124
  testing.tRunner()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1689 +0x180
  testing.(*T).Run.gowrap1()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1742 +0x40

Goroutine 11 (finished) created at:
  command-line-arguments.TestRaces()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:34 +0x124
  testing.tRunner()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1689 +0x180
  testing.(*T).Run.gowrap1()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1742 +0x40
==================
==================
WARNING: DATA RACE
Read at 0x00c000020240 by goroutine 10:
  github.com/posthog/posthog-go.(*SizeLimitedMap).contains()
      /Users/roman/Code/trial/posthog-go/util.go:32 +0x7a8
  github.com/posthog/posthog-go.(*client).GetFeatureFlag()
      /Users/roman/Code/trial/posthog-go/posthog.go:287 +0x120
  github.com/posthog/posthog-go.(*client).IsFeatureEnabled()
      /Users/roman/Code/trial/posthog-go/posthog.go:252 +0xc0
  command-line-arguments.TestRaces.func1()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:41 +0x18c

Previous write at 0x00c000020240 by goroutine 11:
  github.com/posthog/posthog-go.(*SizeLimitedMap).add()
      /Users/roman/Code/trial/posthog-go/util.go:26 +0x6a8
  github.com/posthog/posthog-go.(*client).GetFeatureFlag()
      /Users/roman/Code/trial/posthog-go/posthog.go:297 +0x488
  github.com/posthog/posthog-go.(*client).IsFeatureEnabled()
      /Users/roman/Code/trial/posthog-go/posthog.go:252 +0xc0
  command-line-arguments.TestRaces.func1()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:41 +0x18c

Goroutine 10 (running) created at:
  command-line-arguments.TestRaces()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:34 +0x124
  testing.tRunner()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1689 +0x180
  testing.(*T).Run.gowrap1()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1742 +0x40

Goroutine 11 (finished) created at:
  command-line-arguments.TestRaces()
      /Users/roman/Code/trial/posthog-go/cmd/roman/roman_test.go:34 +0x124
  testing.tRunner()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1689 +0x180
  testing.(*T).Run.gowrap1()
      /nix/store/pi4myqk3ssdk2lp6z05h3yywknlr07i5-go-1.22.1/share/go/src/testing/testing.go:1742 +0x40
==================
posthog 2024/04/17 16:09:57 INFO: flushing 1 messages
posthog 2024/04/17 16:09:57 INFO: response 200 OK
--- FAIL: TestRaces (8.17s)
    testing.go:1398: race detected during execution of test
FAIL
FAIL	command-line-arguments	8.306s
FAIL

zaynetro avatar Apr 17 '24 13:04 zaynetro

@neilkakkar I've run provided example multiple times, I think this problem has been fixed. I'll try to checkout the old version and test it there.

orian avatar May 21 '25 16:05 orian

This might've been fixed by https://github.com/PostHog/posthog-go/issues/80

zaynetro avatar May 21 '25 16:05 zaynetro

I'm gonna close it now, please reopen if reoccurrence happens

orian avatar May 22 '25 10:05 orian