test: RuntimePolicies: Fix flake when validating logs

[pchaigno]

For the first test executed as part of RuntimePolicies, the validation of logs may include logs from the BeforeAll block's execution. Given we restart Cilium in that block, it may lead to JoinEP messages in logs if Cilium was stopped while endpoints were being regenerated.

An example of such a flake is visible at Cilium-PR-Runtime-4.9#3207. That test failed because JoinEP messages were found in logs. Using timestamps from test-output.log, we can check that the validation of logs included the BeforeAll block:

18:58:10 STEP: Running BeforeAll block for EntireTestsuite RuntimePolicies
[...]
19:03:27 STEP: Running JustAfterEach block for EntireTestsuite RuntimePolicies
time="2021-01-05T19:03:27Z" level=debug msg="running command: sudo journalctl -au cilium --since '316.7919274 seconds ago'"

This pull request changes our validation of logs in RuntimePolicies to ensure we only validate logs that correspond to the current test, excluding BeforeAll/BeforeEach blocks.

Related: e558100 ("test: RuntimeKVStoreTest: Fix flake when validating logs")

[pchaigno]

retest-runtime

[aditighag]

I get the intention, but it looks like this change will skip validating logs in the initial set up phases like -

Expect(vm.SetUpCiliumWithHubble()).To(BeNil())
ExpectCiliumReady(vm)

What if there is a panic in starting the cilium agent?

[pchaigno]

What if there is a panic in starting the cilium agent?

If there is a panic in starting the agent, the tests won't be able to pass anyway. They will fail with the usual "beforeAll failures". I think that's preferable given it highlights it's not the test itself failing but its preparation.

[aditighag]

But doesn't it defeat the purpose of having ValidateNoErrorsInLogs? Aren't the cilium start-up logs are as critical, if not more when highlighting/validating logs in test runs?

// ValidateNoErrorsInLogs checks in cilium logs since the given duration (By
// default `CurrentGinkgoTestDescription().Duration`) do not contain `panic`,
// `deadlocks` or `segmentation faults` messages . In case of any of these
// messages, it'll mark the test as failed.

The test should be marked as failed when there are any of these messages in the start-up phase too. What do you think?

[pchaigno]

But doesn't it defeat the purpose of having ValidateNoErrorsInLogs? Aren't the cilium start-up logs are as critical, if not more when highlighting/validating logs in test runs?

Yes, but in this case, we start Cilium with our default configuration, which we already do in a bunch of other places. So if any of these "bad messages" pop up during startup here, they also will in other places.
That said, I agree we should ideally fail if those messages appear in this Cilium startup. Maybe we could add a call to ValidateNoErrorsInLogs in the BeforeAll block here. WDYT?

[aditighag]

But doesn't it defeat the purpose of having ValidateNoErrorsInLogs? Aren't the cilium start-up logs are as critical, if not more when highlighting/validating logs in test runs?

Yes, but in this case, we start Cilium with our default configuration, which we already do in a bunch of other places. So if any of these "bad messages" pop up during startup here, they also will in other places.
That said, I agree we should ideally fail if those messages appear in this Cilium startup. Maybe we could add a call to ValidateNoErrorsInLogs in the BeforeAll block here. WDYT?

If I understand correctly, we want to validate logs from BeforeAll (once) as well as during every test run? I wonder if we make another call to ValidateNoErrorsInLogs in addition to JustAfterEach, would we get the desired behavior?

This is what I have in mind (I'm not sure if you also suggested something similar) -

BeforeAll(func() {
testStartTime = time.Now()
: 

vm.ValidateNoErrorsInLogs(time.Since(testStartTime))
}

& 

JustBeforeEach and JustAfterEach from your current patch

[pchaigno]

If I understand correctly, we want to validate logs from BeforeAll (once) as well as during every test run?

Yes. Your snippet of code is also what I had in mind :-)

I'll update the branch.

[pchaigno]

Hm, actually, if we do that, we'll get error from the previous shutdown again. We should stop Cilium, register time.Now(), then only start Cilium and check the logs. I'll update tomorrow morning.

[pchaigno]

test-me-please

[aditighag]

LGTM!

We need to stop and start Cilium separately (vs. doing a restart)

Now that we are stopping cilium process, do we need to update the restart command that we were executing earlier?

This is where cilium is being restarted, but looks the function is called from couple of other places so we might just leave it as-is -

cilium/test/helpers/cilium.go

Line 918 in f0d509e

res = s.Exec("sudo systemctl restart cilium")

[pchaigno]

The Runtime CI pipeline is passing and reviews are in, so I think this is ready to merge.