Skip to content

Commit

Permalink
CI: e2e: add delay before podman logs or journalctl
Browse files Browse the repository at this point in the history 
...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:

   systemd/systemd#28650

Workaround: Sleep(1) before every 'podman logs' or 'journalctl'.
Better ideas welcome.

This addresses, but does not close, containers#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 <santiago@redhat.com>
  • Loading branch information
@edsantiago
edsantiago committed Aug 4, 2023
1 parent baacbb1 commit 74dc9b7
Show file tree
Hide file tree
Showing 3 changed files with 44 additions and 0 deletions.
3 changes: 3 additions & 0 deletions test/e2e/containers_conf_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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())
Expand Down
39 changes: 39 additions & 0 deletions test/e2e/logs_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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))
Expand All @@ -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))
Expand All @@ -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))
Expand All @@ -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))
Expand Down Expand Up @@ -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))
Expand All @@ -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))
Expand All @@ -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))
Expand All @@ -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))
Expand All @@ -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))
Expand All @@ -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)
Expand Down Expand Up @@ -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))
Expand All @@ -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))
Expand All @@ -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))
Expand All @@ -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))
Expand Down Expand Up @@ -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() {
Expand All @@ -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())
Expand All @@ -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())
Expand Down Expand Up @@ -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))
Expand All @@ -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))
Expand Down
2 changes: 2 additions & 0 deletions test/e2e/play_kube_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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))
Expand Down

0 comments on commit 74dc9b7

Please sign in to comment.