Avoid RemoteSocket collisions in e2e tests

[mtrmac]

What this PR does / why we need it:

Per #12155, we see RemoteSocket collisions. So,

• Add a lock file mechanism to ensure we only generate a RemoteSocket value once, removing even the slightest possibility of a flake due to a collision in ID values
• Add logging on when/where the RemoteSocket values are generated, to maybe help diagnose unexpected RemoteSocket reuse.
• Add somewhat desperate logging when a collision in the generated ID happens, to maybe explain how it can happen (with such a fairly high frequency) in the first place.

How to verify it

CI should continue to run. (I didn’t test this manually even once.) Probably new log entries.

Which issue(s) this PR fixes:

Possibly #12155 , unknown.

Special notes for your reviewer:

[openshift-ci]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: mtrmac

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

• OWNERS [mtrmac]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

[cevich]

Opened test PR that incorporates the failing PR and this one, then only runs the remote tests where collisions were observed.

[cevich]

@mtrmac (and @edsantiago if you're interested) so the good news is your changes here work, they allow the tests to pass collision free. The bad news is...searching for "RemoteSocket collision" log messages finds a TON of hits. Comment with links to annotated logs.

[cevich]

Ultra-curios: I searched through the logs for duplicate mentions of the seed and time from two collision messages. I found none. So somehow we're generating (or leaking) a duplicate IDs without hitting the new logging code 😦

[mtrmac]

Ultra-curios: I searched through the logs for duplicate mentions of the seed and time from two collision messages. I found none

If this is about the cryptoseed values, that’s not too surprising: those values are freshly generated, not actually used to generate the IDs. They are logged primarily for the accompanying error value (and perhaps to see if the seed values are weird, like all zeros or something).

At this point, for the hypothesis in #12155 (comment) , it would be useful to log:

• GinkgoRandomSeed + PID, to confirm all tests share the seed
• Every math/rand.seed call (and possibly the value) + PID, to see which of the seed calls actually matters.

[mtrmac]

I have updated this PR to include such logs, and marked it as draft because it modifies vendored code, which we definitely don’t want in a production release.

(@cevich the vendor edits might also cause test failures, if so I’d appreciate if you could include the extra logs and bypass those failures in your #12169 .)

[cevich]

I’d appreciate if you could include the extra logs and bypass those failures

Happy to, that's why I made that PR...

[cevich]

Clarification: "include the extra logs" - do I need to do anything special for this? I think we already run ginkgo in -v (verbose) mode, so will that capture all the warning-level messages?

[mtrmac]

Clarification: "include the extra logs" - do I need to do anything special for this?

Include the today’s version of the changes in this PR (and on top, add something that bypasses the failures already visible in this PR, caused by edits to vendor/*)

[cevich]

OIC, yes I simply rebased the test PR ontop of this one. The test PR already skips all tasks except for 'build' and 'remote XYZ' (so validate, consistency, etc. are all skipped already). And just for FYI (in case I'm not around) this is done by getting out your butter-knife, and spreading around skip: $CI == $CI everywhere in .cirrus.yml (and clobbering all only_if lines as well) 😀

Sadly, doing something logical like 1 == 0 will break the universe 😢

[cevich]

Results:

• int remote fedora-33 root host
• int remote fedora-34 root host
• int remote ubuntu-2104 root host

So as I suspected, the ginko seed is constant, but maybe all the "collision" message are helpful? I searched for a few, but didn't find any duplicate seeds mentioned 😢

[cevich]

Focusing a bit, from int remote fedora-34 root host, I see two clashes near the beginning, with different PIDs:

1. podman pod container dontshare PIDNS
2. podman pod container share Namespaces

[mtrmac]

I guess the log messages need more improvement.

• We don’t really care about how the Podman being tested seeds the RNG (which is all over the log), we want to see how the test runners seed their RNG. Looking at the logs, I’m not sure that is actually recorded; is it?
• The seed logs should all include PIDs, so that we can actually tell which one is the latest.

[cevich]

Well if we're just going based on PIDs, it looks like podman pod container share Namespaces happened first then podman pod container dontshare PIDNS.

Taking a step back...we still haven't answered the most basic question of: Are we somehow unexpectedly sharing state w/in ginkgo, such that the socket filename is leaking from one test to another (i.e. the string, not the random id). In other words, maybe it's not a RNG problem at all.

[cevich]

we want to see how the test runners seed their RNG. Looking at the logs, I’m not sure that is actually recorded; is it?

If it's there, I don't see it. Ginkgo does report:

[+0135s] Running Suite: Libpod Suite
         ===========================
         Random Seed: 1636041696

Which matches the log messages, but this is all expected. My understanding is ginkgo uses this seed to randomize the order in which tests are run. You can specify it on the command-line (-seed) to force a specific order. But I'm not sure whether/not/how this seed relates to our tests, are you suggesting it is?

[mtrmac]

I’d like to see logrus output by the test process itself (the Go code that calls …/ginkgo/… packages); not logrus output of the Podman being tested (like podman container create). I’m not sure whether that’s the same output as the primary Ginkgo log tracking steps like It/BeforeEach, and listing what failed and how, or whether it’s a separate stream.

[mtrmac]

My hypothesis is that of 5 five rand.Seed calls, the Ginkgo -seed value is, via GinkgoRandomSeed, the one that “wins” and is used by all test runners, causing them to generate the same random values.

[cevich]

the Go code that calls …/ginkgo/… packages

Ginkgo is called by the Makefile

causing them to generate the same random values.

I think we can prove this by (for example) forcing it to always call ginkgo ... -seed 12345, and see if the socket filenames are all the same from one run to the next. Ya?

[cevich]

Maybe this is a dumb question...Shouldn't there be a call to stringid.init() somewhere in test/e2e/*.go? I find none.

Edit (answer): golang calls these init() functions automatically.

[mtrmac]

I have dropped all the extra logging. I don’t know how to find out the exact cause of the collisions, but in #12155 we at least have pointers to the seed only being 31 bits wide, which feels low enough that collisions just might happen from time to time. And anyway, this code should work regardless of the exact cause or exact frequency of the collisions.

[mheon]

Changes LGTM. Tests are red, I think this needs a rebase to pick up the upstream testing fix.

[cevich]

This LGTM also, but I think it should also include a change to test/utils.go to not use the super-duper evil GinkgoRandomSeed(). We don't want that anywhere in our code.

[mtrmac]

This LGTM also, but I think it should also include a change to test/utils.go to not use the super-duper evil GinkgoRandomSeed(). We don't want that anywhere in our code.

It might be interesting to discuss what RNG behavior we want,

1. A constant one, to maximize likelihood of collisions
2. The semi-constant GinkgoRandomSeed, to have likely collisions but to test different outcomes over time
3. An uniformly random one, to minimize collisions

… ultimately, at least per the log in #12155 (comment) (on macOS; I guess it’s possible that Linux uses a different order), nothing we do in test/utils.go actually matters.

If we want to control the RNG seeding, AFAICS all relevant code must use a private RNG, not the shared one. Until then, removing that line would look good but probably not change any outcome.

[cevich]

nothing we do in test/utils.go actually matters.

So it's effectively dead-code, let's just remove it then. Avoid causing any confusion and desk-pounding to some future developer who encounters it.

[cevich]

I didn't dig into it, but you may need to rebase again to fix the checkpoint tests failures (log). There was a flurry of PRs that went in right before my F35 one merged. Not sure if you picked them all up or not.

Edit: nevermind, you've got them. Those are new/flakes.

[mtrmac]

nothing we do in test/utils.go actually matters.

So it's effectively dead-code, let's just remove it then.

That’s a good point; adding a commit to drop that, as suggested.

[github-actions]

A friendly reminder that this PR had no activity for 30 days.

[rhatdan]

@cevich @edsantiago @mtrmac Any reason not to merge this?

[rhatdan]

/lgtm