From 3ba6bac7339864c7a62cd1e7b6d4616bc0781c3e 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 | 33 ++++++++++++++++++++++++++++++++ test/e2e/play_kube_test.go | 2 ++ 3 files changed, 38 insertions(+) diff --git a/test/e2e/containers_conf_test.go b/test/e2e/containers_conf_test.go index 0eed5efe874e..adaee0eea7d6 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) 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..13560ca28cdc 100644 --- a/test/e2e/logs_test.go +++ b/test/e2e/logs_test.go @@ -109,6 +109,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1) results := podmanTest.Podman([]string{"logs", "--tail", "99", name}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -139,6 +141,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1) results := podmanTest.Podman([]string{"logs", "--tail", "800", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -157,6 +161,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1) results := podmanTest.Podman([]string{"logs", "--tail", "2", "-t", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -175,6 +181,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1) results := podmanTest.Podman([]string{"logs", "--since", "2017-08-07T10:10:09.056611202-04:00", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -193,6 +201,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1) results := podmanTest.Podman([]string{"logs", "--since", "10m", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -211,6 +221,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1) results := podmanTest.Podman([]string{"logs", "--until", "10m", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -229,6 +241,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1) now := time.Now() now = now.Add(time.Minute * 1) nowS := now.Format(time.RFC3339) @@ -363,6 +377,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) results := podmanTest.Podman([]string{"logs", cid}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -380,6 +396,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1) results := podmanTest.Podman([]string{"logs", "test"}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -401,6 +419,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1) results := podmanTest.Podman([]string{"logs", cname}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -421,6 +441,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) logs := podmanTest.Podman([]string{"logs", cname}) logs.WaitWithDefaultTimeout() Expect(logs).To(Exit(0)) @@ -488,6 +510,8 @@ var _ = Describe("Podman logs", func() { log2.WaitWithDefaultTimeout() Expect(log2).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1) results := podmanTest.Podman([]string{"pod", "logs", "-l"}) results.WaitWithDefaultTimeout() if IsRemote() { @@ -512,6 +536,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1) 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 +556,8 @@ var _ = Describe("Podman logs", func() { wait.WaitWithDefaultTimeout() Expect(wait).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1) 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 +594,8 @@ var _ = Describe("Podman logs", func() { log2.WaitWithDefaultTimeout() Expect(log2).To(Exit(0)) + // Flake prevention: journalctl makes no timeliness guarantees. + time.Sleep(1) results := podmanTest.Podman([]string{"pod", "logs", "--names", podName}) results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) @@ -589,6 +619,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) 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..6c0aa2fd05dc 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) logs := podmanTest.Podman([]string{"logs", getCtrNameInPod(p)}) logs.WaitWithDefaultTimeout() Expect(logs).Should(Exit(0))