From ada4e1a8c185f3329a6abdafc5b294c0692fdd36 Mon Sep 17 00:00:00 2001 From: Paul Holzinger Date: Tue, 2 Jul 2024 11:26:49 +0200 Subject: [PATCH 1/3] pkg/machine/e2e: improve timeout handling In case of timeouts actually log the command again and make sure to send SIGABRT to the process as go will create a useful stack strace where we can see where things are hanging. It also kill the process unlike the default Eventually().Should(Exit()) call the leaves the process around. The output will be captured by default in the log so we just see the stack trace there. And while at it bump the timout up to 10 mins, we are hitting hard flakes in CI where machine init takes longer than 5 mins for unknown reasons but this seems to be good enough. Signed-off-by: Paul Holzinger --- pkg/machine/e2e/config_test.go | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/pkg/machine/e2e/config_test.go b/pkg/machine/e2e/config_test.go index ddfeb16662..e4ed0f8f7b 100644 --- a/pkg/machine/e2e/config_test.go +++ b/pkg/machine/e2e/config_test.go @@ -9,6 +9,7 @@ import ( "slices" "strconv" "strings" + "syscall" "time" "github.com/containers/podman/v5/pkg/machine" @@ -24,7 +25,7 @@ import ( var originalHomeDir = os.Getenv("HOME") const ( - defaultTimeout = 240 * time.Second + defaultTimeout = 10 * time.Minute ) type machineCommand interface { @@ -53,7 +54,16 @@ type machineTestBuilder struct { // waitWithTimeout waits for a command to complete for a given // number of seconds func (ms *machineSession) waitWithTimeout(timeout time.Duration) { - Eventually(ms, timeout).Should(Exit()) + Eventually(ms, timeout).Should(Exit(), func() string { + // Note eventually does not kill the command as such the command is leaked forever without killing it + // Also let's use SIGABRT to create a go stack trace so in case there is a deadlock we see it. + ms.Signal(syscall.SIGABRT) + // Give some time to let the command print the output so it is not printed much later + // in the log at the wrong place. + time.Sleep(1 * time.Second) + return fmt.Sprintf("command timed out after %fs: %v", + timeout.Seconds(), ms.Command.Args) + }) } func (ms *machineSession) Bytes() []byte { From 527c0f0bfa39887a7751cf58ae18ca2e5f32cbd9 Mon Sep 17 00:00:00 2001 From: Paul Holzinger Date: Fri, 5 Jul 2024 14:19:23 +0200 Subject: [PATCH 2/3] pkg/machine/e2e: run debug commands after init To debug the slow machine init command. Let's see the disk image size. Signed-off-by: Paul Holzinger --- pkg/machine/e2e/config_test.go | 27 ++++++++++++++++++++++++++- 1 file changed, 26 insertions(+), 1 deletion(-) diff --git a/pkg/machine/e2e/config_test.go b/pkg/machine/e2e/config_test.go index e4ed0f8f7b..081cc8a067 100644 --- a/pkg/machine/e2e/config_test.go +++ b/pkg/machine/e2e/config_test.go @@ -49,6 +49,7 @@ type machineTestBuilder struct { names []string podmanBinary string timeout time.Duration + isInit bool } // waitWithTimeout waits for a command to complete for a given @@ -139,6 +140,10 @@ func (m *machineTestBuilder) setCmd(mc machineCommand) *machineTestBuilder { m.names = append(m.names, m.name) } m.cmd = mc.buildCmd(m) + + _, ok := mc.(*initMachine) + m.isInit = ok + return m } @@ -166,7 +171,27 @@ func (m *machineTestBuilder) runWithoutWait() (*machineSession, error) { } func (m *machineTestBuilder) run() (*machineSession, error) { - return runWrapper(m.podmanBinary, m.cmd, m.timeout, true) + s, err := runWrapper(m.podmanBinary, m.cmd, m.timeout, true) + if m.isInit { + c := exec.Command("du", "-ah", filepath.Join(os.Getenv("HOME"), ".local/share/containers/podman/machine/applehv")) + c.Stderr = os.Stderr + c.Stdout = os.Stdout + GinkgoWriter.Println(c.Args) + _ = c.Run() + + c = exec.Command("ls", "-lh", filepath.Join(os.Getenv("HOME"), ".local/share/containers/podman/machine/applehv")) + c.Stderr = os.Stderr + c.Stdout = os.Stdout + GinkgoWriter.Println(c.Args) + _ = c.Run() + + c = exec.Command("stat", filepath.Join(os.Getenv("HOME"), ".local/share/containers/podman/machine/applehv", m.name+"-arm64.raw")) + c.Stderr = os.Stderr + c.Stdout = os.Stdout + GinkgoWriter.Println(c.Args) + _ = c.Run() + } + return s, err } func runWrapper(podmanBinary string, cmdArgs []string, timeout time.Duration, wait bool) (*machineSession, error) { From 5e3d821814459507eead2945436cbff9f5e09d45 Mon Sep 17 00:00:00 2001 From: Paul Holzinger Date: Fri, 5 Jul 2024 14:29:22 +0200 Subject: [PATCH 3/3] pkg/machine/e2e: print tests timings at the end Makes it easier to see which tests are slow. Signed-off-by: Paul Holzinger --- pkg/machine/e2e/machine_test.go | 27 ++++++++++++++++++++++++++- 1 file changed, 26 insertions(+), 1 deletion(-) diff --git a/pkg/machine/e2e/machine_test.go b/pkg/machine/e2e/machine_test.go index 3f7415d870..d825bf7bbc 100644 --- a/pkg/machine/e2e/machine_test.go +++ b/pkg/machine/e2e/machine_test.go @@ -1,13 +1,16 @@ package e2e_test import ( + "cmp" "errors" "fmt" "os" "path/filepath" "runtime" + "slices" "strings" "testing" + "time" "github.com/containers/common/pkg/config" "github.com/containers/podman/v5/pkg/machine/define" @@ -75,7 +78,29 @@ var _ = BeforeSuite(func() { } }) -var _ = SynchronizedAfterSuite(func() {}, func() {}) +type timing struct { + name string + length time.Duration +} + +var timings []timing + +var _ = AfterEach(func() { + r := CurrentSpecReport() + timings = append(timings, timing{ + name: r.FullText(), + length: r.RunTime, + }) +}) + +var _ = SynchronizedAfterSuite(func() {}, func() { + slices.SortFunc(timings, func(a, b timing) int { + return cmp.Compare(a.length, b.length) + }) + for _, t := range timings { + GinkgoWriter.Printf("%s\t\t%f seconds\n", t.name, t.length.Seconds()) + } +}) func setup() (string, *machineTestBuilder) { // Set TMPDIR if this needs a new directory