From 74dc9b765b00ed27a6f54b7f7c12f4730cb86100 Mon Sep 17 00:00:00 2001 From: Ed Santiago Date: Wed, 2 Aug 2023 16:29:28 -0600 Subject: [PATCH] CI: e2e: add delay before podman logs or journalctl ...to reduce flakes. Reason: journald makes no guarantees. Just because a systemd job has finished, or podman has written+flushed log entries, doesn't mean that journald will actually know about them: https://github.com/systemd/systemd/issues/28650 Workaround: Sleep(1) before every 'podman logs' or 'journalctl'. Better ideas welcome. This addresses, but does not close, #18501. That's a firehose, with many more failures than I can possibly cross-reference. I will leave it open, then keep monitoring missing-logs flakes over time, and pick those off as they occur. Signed-off-by: Ed Santiago --- test/e2e/containers_conf_test.go | 3 +++ test/e2e/logs_test.go | 39 ++++++++++++++++++++++++++++++++ test/e2e/play_kube_test.go | 2 ++ 3 files changed, 44 insertions(+) diff --git a/test/e2e/containers_conf_test.go b/test/e2e/containers_conf_test.go index 0eed5efe874e..521175b2bae5 100644 --- a/test/e2e/containers_conf_test.go +++ b/test/e2e/containers_conf_test.go @@ -6,6 +6,7 @@ import ( "os/exec" "path/filepath" "strings" + "time" "github.com/containers/podman/v4/libpod/define" . "github.com/containers/podman/v4/test/utils" @@ -254,6 +255,8 @@ var _ = Describe("Verify podman containers.conf usage", func() { wait.WaitWithDefaultTimeout() Expect(wait).Should(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) cmd := exec.Command("journalctl", "--no-pager", "-o", "json", "--output-fields=CONTAINER_TAG", fmt.Sprintf("CONTAINER_ID_FULL=%s", cid)) out, err := cmd.CombinedOutput() Expect(err).ToNot(HaveOccurred()) diff --git a/test/e2e/logs_test.go b/test/e2e/logs_test.go index c14750d2b904..3d6b55f2dc36 100644 --- a/test/e2e/logs_test.go +++ b/test/e2e/logs_test.go @@ -54,6 +54,8 @@ var _ = Describe("Podman logs", func() { results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results = podmanTest.Podman([]string{"logs", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -73,6 +75,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results := podmanTest.Podman([]string{"logs", "--tail", "2", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -91,6 +95,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results := podmanTest.Podman([]string{"logs", "--tail", "0", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -109,6 +115,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results := podmanTest.Podman([]string{"logs", "--tail", "99", name}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -139,6 +147,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results := podmanTest.Podman([]string{"logs", "--tail", "800", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -157,6 +167,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results := podmanTest.Podman([]string{"logs", "--tail", "2", "-t", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -175,6 +187,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results := podmanTest.Podman([]string{"logs", "--since", "2017-08-07T10:10:09.056611202-04:00", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -193,6 +207,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results := podmanTest.Podman([]string{"logs", "--since", "10m", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -211,6 +227,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results := podmanTest.Podman([]string{"logs", "--until", "10m", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -229,6 +247,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) now := time.Now() now = now.Add(time.Minute * 1) nowS := now.Format(time.RFC3339) @@ -363,6 +383,8 @@ var _ = Describe("Podman logs", func() { Expect(inspect).To(Exit(0)) Expect(inspect.OutputToString()).To(Equal("10kB")) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results := podmanTest.Podman([]string{"logs", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -380,6 +402,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results := podmanTest.Podman([]string{"logs", "test"}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -401,6 +425,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results := podmanTest.Podman([]string{"logs", cname}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -421,6 +447,8 @@ var _ = Describe("Podman logs", func() { // However this test must make sure that there is no such extra newline. Expect(string(logc.Out.Contents())).To(Equal(content)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) logs := podmanTest.Podman([]string{"logs", cname}) logs.WaitWithDefaultTimeout() Expect(logs).To(Exit(0)) @@ -488,6 +516,8 @@ var _ = Describe("Podman logs", func() { log2.WaitWithDefaultTimeout() Expect(log2).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results := podmanTest.Podman([]string{"pod", "logs", "-l"}) results.WaitWithDefaultTimeout() if IsRemote() { @@ -512,6 +542,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) cmd := exec.Command("journalctl", "--no-pager", "-o", "json", "--output-fields=CONTAINER_TAG", fmt.Sprintf("CONTAINER_ID_FULL=%s", cid)) out, err := cmd.CombinedOutput() Expect(err).ToNot(HaveOccurred()) @@ -530,6 +562,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) cmd := exec.Command("journalctl", "--no-pager", "-o", "json", "--output-fields=CONTAINER_NAME", fmt.Sprintf("CONTAINER_ID_FULL=%s", cid)) out, err := cmd.CombinedOutput() Expect(err).ToNot(HaveOccurred()) @@ -566,6 +600,8 @@ var _ = Describe("Podman logs", func() { log2.WaitWithDefaultTimeout() Expect(log2).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results := podmanTest.Podman([]string{"pod", "logs", "--names", podName}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -589,6 +625,9 @@ var _ = Describe("Podman logs", func() { log2 := podmanTest.Podman([]string{"run", "--name", containerName2, "--pod", podName, BB, "echo", "log2"}) log2.WaitWithDefaultTimeout() Expect(log2).To(Exit(0)) + + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) results := podmanTest.Podman([]string{"pod", "logs", "--color", podName}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) diff --git a/test/e2e/play_kube_test.go b/test/e2e/play_kube_test.go index 886ab70eb51a..71de4b247420 100644 --- a/test/e2e/play_kube_test.go +++ b/test/e2e/play_kube_test.go @@ -2310,6 +2310,8 @@ var _ = Describe("Podman play kube", func() { wait.WaitWithDefaultTimeout() Expect(wait).Should(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1 * time.Second) logs := podmanTest.Podman([]string{"logs", getCtrNameInPod(p)}) logs.WaitWithDefaultTimeout() Expect(logs).Should(Exit(0))