PostHog / posthog-go

Official PostHog Go library
MIT License
20 stars 17 forks source link

Data races with feature flag poller #30

Open zaynetro opened 6 months ago

zaynetro commented 6 months ago

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 commented 4 months ago

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 commented 4 months ago

indeed, thanks!

zaynetro commented 4 months ago

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 ```