CI: RuntimePrivilegedUnitTests TestArpPingHandling failed, timeout reached while waiting for condition

[tklauser]

	 node_linux_test.go:1207:
	     wait(nodev1.Identity(), nil, true)
	 node_linux_test.go:1048:
	     c.Assert(err, check.IsNil)
	 ... value *errors.errorString = &errors.errorString{s:"timeout reached while waiting for condition"} ("timeout reached while waiting for condition")
	 
	 START: node_linux_test.go:138: linuxPrivilegedIPv4OnlyTestSuite.TearDownTest
	 PASS: node_linux_test.go:138: linuxPrivilegedIPv4OnlyTestSuite.TearDownTest	0.052s
	 
	 FAIL: node_linux_test.go:956: linuxPrivilegedIPv4OnlyTestSuite.TestArpPingHandling

This failed on #16210 (a 1.10 backport PR) and it looks like #16072 was in place.

https://jenkins.cilium.io/job/Cilium-PR-Runtime-4.9/4731/

test_results_Cilium-PR-Runtime-4.9_4731_BDD-Test-PR.zip

Previously: #16075 (looks like this one appeared again in another PR), #16040, #14640, #14125

/cc @brb

[pchaigno]

Hit on a v1.9 backport PR: https://jenkins.cilium.io/job/Cilium-PR-Runtime-4.9/4801/testReport/junit/(root)/Suite-runtime/RuntimePrivilegedUnitTests_Run_Tests/.
31c1bee4_RuntimePrivilegedUnitTests_Run_Tests.zip

[jibi]

I can reproduce this on a 4.9 dev VM:

vagrant@k8s1:~/go/src/github.com/cilium/cilium/pkg/datapath/linux$ while true; do sudo go test . -count=1 -tags=privileged_tests; done
ok  	github.com/cilium/cilium/pkg/datapath/linux	8.123s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.848s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.791s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.562s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.968s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.763s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.837s
ok  	github.com/cilium/cilium/pkg/datapath/linux	8.844s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.558s
ok  	github.com/cilium/cilium/pkg/datapath/linux	8.144s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.722s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.922s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.899s
ok  	github.com/cilium/cilium/pkg/datapath/linux	8.127s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.784s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.709s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.577s
ok  	github.com/cilium/cilium/pkg/datapath/linux	8.542s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.522s
ok  	github.com/cilium/cilium/pkg/datapath/linux	9.027s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.844s
ok  	github.com/cilium/cilium/pkg/datapath/linux	8.807s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.689s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.831s
ok  	github.com/cilium/cilium/pkg/datapath/linux	8.105s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.834s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.651s
ok  	github.com/cilium/cilium/pkg/datapath/linux	8.013s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.519s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.765s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.796s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.721s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.925s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.958s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.699s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.658s
ok  	github.com/cilium/cilium/pkg/datapath/linux	8.711s
ok  	github.com/cilium/cilium/pkg/datapath/linux	8.084s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.555s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.784s
ok  	github.com/cilium/cilium/pkg/datapath/linux	7.717s

----------------------------------------------------------------------
FAIL: node_linux_test.go:956: linuxPrivilegedIPv4OnlyTestSuite.TestArpPingHandling

node_linux_test.go:1207:
    wait(nodev1.Identity(), nil, true)
node_linux_test.go:1048:
    c.Assert(err, check.IsNil)
... value *errors.errorString = &errors.errorString{s:"timeout reached while waiting for condition"} ("timeout reached while waiting for condition")

OOPS: 21 passed, 1 FAILED
--- FAIL: Test (12.39s)
FAIL
FAIL	github.com/cilium/cilium/pkg/datapath/linux	12.403s
FAIL
ok  	github.com/cilium/cilium/pkg/datapath/linux	8.040s

@brb do you have any pointers/context from previous investigations about this flake?

[tklauser]

@aditighag I assume this was closed by mistake? Or is this fixed already?

[aditighag]

I'm not sure how that happened. Sorry! 😕

[brb]

do you have any pointers/context from previous investigations about this flake?

@jibi I think I know what's happening. We don't wait for goroutines (started at https://github.com/cilium/cilium/blob/v1.10.0/pkg/datapath/linux/node_linux_test.go#L1161-L1174) to finish. So they can keep updating the ARP entries making the wait to time out.

Could you try the following patch?

diff --git a/pkg/datapath/linux/node_linux_test.go b/pkg/datapath/linux/node_linux_test.go
index 20f965bf6..e7f3e287c 100644
--- a/pkg/datapath/linux/node_linux_test.go
+++ b/pkg/datapath/linux/node_linux_test.go
@@ -1201,6 +1201,7 @@ func (s *linuxPrivilegedIPv4OnlyTestSuite) TestArpPingHandling(c *check.C) {
        }
        // Cleanup
        close(done)
+       wg.Wait()
        now = time.Now()
        err = linuxNodeHandler.NodeDelete(nodev1)
        c.Assert(err, check.IsNil)

[jibi]

That seems to work 💥 the entry from linuxNodeHandler.neighNextHopByNode is now properly removed each time and the wait function does not timeout anymore. I'll fill a PR

[brb]

Cool, thanks!