TestInformedWatcher flaky

[runzexia]

/area test-and-release
/kind bug

Expected Behavior

test always success

Actual Behavior

test failed in https://github.com/knative/pkg/runs/1399755328,
after rerun test success

Steps to Reproduce the Problem

not easy to reproduce, but i guess it because informer.HasSynced not means all EventHandler has been called

[runzexia]

failed again https://github.com/knative/pkg/runs/1401922270?check_suite_focus=true

[bobcatfish]

Hi @runzexia !! I think this might be an actual bug and we are running into this in Tekton as well, causing tektoncd/pipeline#2815 (longer explanation in tektoncd/pipeline#2815 (comment))

Looking at the assertion that's failing:

pkg/configmap/informed_watcher_test.go

Lines 86 to 92 in c5296cd

	// When Start returns the callbacks should have been called with the
	// version of the objects that is available.
	for _, obj := range []*counter{foo1, foo2, bar} {
	if got, want := obj.count(), 1; got != want {
	t.Errorf("%v.count = %d, want %d", obj.name, got, want)
	}
	}

It looks like the intention is that after calling cmw.Start, all of the callbacks have been called, but these flakes are showing that that isn't always the case (which I think makes sense b/c the callbacks are called in separate go routines).

I hacked the failing test to run in a loop and added a script to run it repeatedly in bobcatfish@32da803 and every time I run doit.sh I eventually see a failure such as:

+ for i in '`seq 1 1000`'
+ go test ./configmap/... -run TestInformedWatcher -count=1
--- FAIL: TestInformedWatcher (0.00s)
    --- FAIL: TestInformedWatcher/AGAIN-140 (0.00s)
        informed_watcher_test.go:94: foo1.count = 0, want 1
FAIL
FAIL	knative.dev/pkg/configmap	2.319s

In Tekton this means that there is a chance that when a controller starts, the values returned by the config store using this watcher might not return the right values (if the go routines that update the config store have not completed).

So I think that InformedWatcher.Start isn't functioning as intended and this is a bug. The fix would be to make it so that InformedWatcher.Start actually somehow guarantees that those callbacks have been invoked before returning, what do you think?

( @mattmoor might be relevant to your interests! )

[mattmoor]

That'd be a good find. cc @dprotaso

which I think makes sense b/c the callbacks are called in separate go routines

Where do you mean? Within the informer itself?

[bobcatfish]

which I think makes sense b/c the callbacks are called in separate go routines

Where do you mean? Within the informer itself?

1. InformedWatcher.Start calls
2. InformedWatcher.registerCallbackAndStartInformer which sets up all the event handlers and then calls
3. sharedInformerFactory.Start which calls
4. go informer.Run which i think waves hands pops events from a queue and ultimately uses this Process function is invoked to call the callbacks from within the goroutine ??

[mattmoor]

I would expect the wait for sync to synchronize things, if the go is just the informer.Run 🤔

pkg/configmap/informed_watcher.go

Line 144 in c5296cd

if ok := cache.WaitForCacheSync(stopCh, i.informer.Informer().HasSynced); !ok {

[runzexia]

I would expect the wait for sync to synchronize things, if the go is just the informer.Run 🤔

pkg/configmap/informed_watcher.go

Line 144 in c5296cd

if ok := cache.WaitForCacheSync(stopCh, i.informer.Informer().HasSynced); !ok {

I think i.informer.Informer().HasSynced would not guarantee the callback has invoked, thats the problem

[mattmoor]

That is definitely plausible, but it would be good to confirm whether the informer events are done asynchronously, and where that happens. Just want to make sure we understand what's going on. 👍

[bobcatfish]

would be good to confirm whether the informer events are done asynchronously, and where that happens

It seems like the only place the event handlers (OnAdd, OnUpdate, OnDelete) are called is in the Process function (or by the OnUpdate function, also called ultimately in the Process function), and it seems like the Process function is only invoked via informer.Run (via processloop) - so I think the event handler callbacks are only invoked asynchronously? (but maybe there is some other code in play?)

[dprotaso]

I think i.informer.Informer().HasSynced would not guarantee the callback has invoked, thats the problem

@runzexia is right.

so I think the event handler callbacks are only invoked asynchronously

@bobcatfish is right.

[dprotaso]

Digging into the code myself HasSynced is true once the informers backing cache is up to date.

Notifying handlers is async and can be delayed (it has it's own queue)

[bobcatfish]

Hey @dprotaso - it looks like #1929 resolved this issue but it's only changing test code - does this mean we're okay with the potential race condition?

i.e. if you use the informedwatcher too quickly (specifically before the event handling goroutines have been invoked) you won't get the value you wanted?

Over in Tekton Pipelines where we use this to read configuration from config maps i wouldn't want to risk that we use the wrong value (however unlikely it is).

If we don't feel like InformedWatcher.Start should wait for the first sync to happen, I'd like to request that we expose some way to wait for this. Let me know if I need to open another issue.

[dprotaso]

Yeah it's not guaranteed. I guess the severity would depend - ie. sharedmain seems to wait for configmap informers first by calling Start on the watcher. Then it waits again for another set of informers that have been setup via injection.

I think it'd be hard to provide guarantees that a set of event handler were invoked. You may way to just fail reconciliation if there's some configuration that's not present but expected.

It's worth discussing so feel free to open a new issue.

[bobcatfish]

Okay @dprotaso I've opened #1960 !