Load function can be called multiple times for a single cache key before expiration

[wchargin]

This is related to #242, but the patch in #243 only partially fixed it. That patch makes sure that the load function can't be called twice for the same cache key at the same time, but doesn't do anything to prevent the load function from being called twice sequentially for the same cache key.

Steps for Reproduction

Here is a short standalone program to demonstrate the issue:

package main

import (
	"context"
	"fmt"
	"os"
	"time"
	"runtime/debug"

	"github.com/eko/gocache/lib/v4/cache"
	gocacheStore "github.com/eko/gocache/store/go_cache/v4"
	gocache "github.com/patrickmn/go-cache"
)

func main() {
	// Verify dependency version
	if bi, ok := debug.ReadBuildInfo(); ok {
		for _, dep := range bi.Deps {
			if dep.Path == "github.com/eko/gocache/lib/v4" {
				fmt.Println(dep)
			}
		}
	}

	callCount := 0
	loader := func(ctx context.Context, key any) (struct{}, error) {
		fmt.Printf("loading cache for key %T %v\n", key, key)
		callCount++
		return struct{}{}, nil
	}

	cacheClient := gocache.New(5*time.Minute, 10*time.Minute)
	cacheStore := gocacheStore.NewGoCache(cacheClient)
	cache := cache.NewLoadable[struct{}](loader, cache.New[struct{}](cacheStore))

	ctx := context.Background()

	cache.Get(ctx, 1)
	//time.Sleep(100 * time.Millisecond) // test passes if you uncomment this!
	cache.Get(ctx, 1)

	fmt.Printf("call count: got %v, want %v\n", callCount, 1)
	if callCount != 1 {
		os.Exit(1)
	}
}

&{github.com/eko/gocache/lib/v4 v4.1.6 h1:5WWIGISKhE7mfkyF+SJyWwqa4Dp2mkdX8QsZpnENqJI= <nil>}
loading cache for key int 1
loading cache for key int 1
call count: got 2, want 1
exit status 1

go.mod

module example.com/m

go 1.22

toolchain go1.22.3

require (
	github.com/eko/gocache/lib/v4 v4.1.6
	github.com/eko/gocache/store/go_cache/v4 v4.2.2
	github.com/patrickmn/go-cache v2.1.0+incompatible
)

require (
	github.com/beorn7/perks v1.0.1 // indirect
	github.com/cespare/xxhash/v2 v2.1.2 // indirect
	github.com/golang/mock v1.6.0 // indirect
	github.com/golang/protobuf v1.5.2 // indirect
	github.com/matttproud/golang_protobuf_extensions v1.0.1 // indirect
	github.com/prometheus/client_golang v1.14.0 // indirect
	github.com/prometheus/client_model v0.3.0 // indirect
	github.com/prometheus/common v0.37.0 // indirect
	github.com/prometheus/procfs v0.8.0 // indirect
	golang.org/x/exp v0.0.0-20240416160154-fe59bbe5cc7f // indirect
	golang.org/x/sync v0.7.0 // indirect
	golang.org/x/sys v0.5.0 // indirect
	google.golang.org/protobuf v1.33.0 // indirect
)

And here is a test case that you can add to loadable_test.go to reproduce it:

func TestLoadFuncOnlyCalledOnce(t *testing.T) {
	ctrl := gomock.NewController(t)
	ctx := context.Background()

	cacheValue := struct{}{}

	cache1 := NewMockSetterCacheInterface[any](ctrl)
	cache1.EXPECT().Get(ctx, "my-key").Return(nil, errors.New("unable to find in cache 1"))
	cache1.EXPECT().Get(ctx, "my-key").Return(nil, errors.New("unable to find in cache 1"))
	cache1.EXPECT().Set(ctx, "my-key", cacheValue).AnyTimes().Return(nil)

	callCount := 0
	loadFunc := func(ctx context.Context, key any) (any, error) {
		callCount++
		return cacheValue, nil
	}

	cache := NewLoadable[any](loadFunc, cache1)
	cache.Get(ctx, "my-key")
	cache.Get(ctx, "my-key")
	assert.Equal(t, callCount, 1)
}

Or, comment out the time.Sleep(time.Millisecond * 10) in the existing test TestLoadableGetWhenAvailableInLoadFunc. Sleeping hides the bug!

Expected behavior

If cache.Get("my-key") is called, completes, and is called again before the cache entry expires, the loader should only be called once.

Actual behavior

The loader can be called many times.

Platforms

Tested on both Linux and macOS; I see the same bug in both places.

Versions

github.com/eko/gocache/lib/v4 v4.1.6 h1:5WWIGISKhE7mfkyF+SJyWwqa4Dp2mkdX8QsZpnENqJI=

[eko]

Hi @wchargin,

Thank you for reporting this issue and providing all the necessary stuff for reproducing.

You're right, the function is called twice, unless singleflight library is calling it twice. I found that it's because the library singleflight itself removes the entry on second call.

Here is the issue change I found: https://github.com/golang/sync/commit/7f9b1623fab7a8a3d219f2a4db1b2fe98fadafea

I'm not sure why this has been done but it seems to cause an issue here because the c variable (which is new(call) in our case) seems to be the same so it's deleted from the map and the second call makes the call again.

Maybe @cuonglm who is the author of this change have any explanation on this?

Thanks

[johnwook]

This looks similar to the issue described in this GitHub comment. In real-world scenarios, calling Get consecutively is unlikely, so this should be fine (I believe ;))

[wchargin]

In real-world scenarios, calling Get consecutively is unlikely, so this should be fine (I believe ;))

I mean, I filed this issue because I was hitting this in the real world… I couldn't find an adequate workaround, and had to switch away from this caching library altogether. If you don't want to prioritize it, that's your choice, but it is certainly a real issue.

[bohdand-weka]

It looks like issue with scheduler, if you add runtime.Gosched() function call in your test - the cache get some time for sync

[wchargin]

Sleeping hides the problem. Calling Gosched() hides the problem. These hacks only prevent a test from catching the issue; they do not fix the actual concurrency bug in the library.