Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Data races with feature flag poller #30

Open
zaynetro opened this issue Feb 2, 2024 · 3 comments
Open

Data races with feature flag poller #30

zaynetro opened this issue Feb 2, 2024 · 3 comments

Comments

@zaynetro
Copy link
Contributor

zaynetro commented Feb 2, 2024

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

@lukfugl
Copy link

lukfugl commented Apr 16, 2024

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.

@neilkakkar
Copy link
Contributor

indeed, thanks!

@zaynetro
Copy link
Contributor Author

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

@neilkakkar neilkakkar reopened this Apr 17, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants