Fix e2e startup test

Do more cleanup between runs, collect more logs on failure.

Signed-off-by: Brad Davidson <brad.davidson@rancher.com>

.github/workflows/e2e.yaml

@@ -101,8 +101,8 @@ jobs:
         uses: actions/upload-artifact@v4
         if: ${{ failure() }}
         with:
-          name: ${{ matrix.etest}}-journald-logs
-          path: tests/e2e/${{ matrix.etest }}/*-jlog.txt
+          name: e2e-${{ matrix.etest}}-logs
+          path: tests/e2e/${{ matrix.etest }}/*log.txt
           retention-days: 30
       - name: On Failure, Launch Debug Session
         uses: lhotari/action-upterm@v1

tests/e2e/btrfs/btrfs_test.go

@@ -75,6 +75,7 @@ var _ = AfterEach(func() {
 var _ = AfterSuite(func() {
 	if failed {
 		Expect(e2e.SaveJournalLogs(tc.Servers)).To(Succeed())
+		Expect(e2e.TailPodLogs(50, tc.AllNodes())).To(Succeed())
 	}
 	if !failed || *ci {
 		Expect(e2e.DestroyCluster()).To(Succeed())

tests/e2e/embeddedmirror/embeddedmirror_test.go

@@ -129,6 +129,7 @@ var _ = AfterEach(func() {
 var _ = AfterSuite(func() {
 	if failed {
 		Expect(e2e.SaveJournalLogs(tc.AllNodes())).To(Succeed())
+		Expect(e2e.TailPodLogs(50, tc.AllNodes())).To(Succeed())
 	} else {
 		Expect(e2e.GetCoverageReport(tc.AllNodes())).To(Succeed())
 	}

tests/e2e/externalip/externalip_test.go

@@ -150,6 +150,7 @@ var _ = AfterEach(func() {
 var _ = AfterSuite(func() {
 	if failed {
 		Expect(e2e.SaveJournalLogs(tc.AllNodes())).To(Succeed())
+		Expect(e2e.TailPodLogs(50, tc.AllNodes())).To(Succeed())
 	} else {
 		Expect(e2e.GetCoverageReport(tc.AllNodes())).To(Succeed())
 	}

tests/e2e/privateregistry/privateregistry_test.go

@@ -134,6 +134,7 @@ var _ = AfterEach(func() {
 var _ = AfterSuite(func() {
 	if failed {
 		Expect(e2e.SaveJournalLogs(tc.AllNodes())).To(Succeed())
+		Expect(e2e.TailPodLogs(50, tc.AllNodes())).To(Succeed())
 	} else {
 		Expect(e2e.GetCoverageReport(tc.AllNodes())).To(Succeed())
 	}

tests/e2e/s3/s3_test.go

@@ -158,6 +158,7 @@ var _ = AfterEach(func() {
 var _ = AfterSuite(func() {
 	if failed {
 		Expect(e2e.SaveJournalLogs(tc.AllNodes())).To(Succeed())
+		Expect(e2e.TailPodLogs(50, tc.AllNodes())).To(Succeed())
 	} else {
 		Expect(e2e.GetCoverageReport(tc.AllNodes())).To(Succeed())
 	}

tests/e2e/startup/Vagrantfile

@@ -36,6 +36,7 @@ def provision(vm, role, role_num, node_num)
       k3s.env = %W[K3S_KUBECONFIG_MODE=0644 #{install_type} INSTALL_K3S_SKIP_START=true]
       k3s.config_mode = '0644' # side-step https://github.com/k3s-io/k3s/issues/4321
       k3s.config = <<~YAML
+        debug: true
         token: vagrant
         node-external-ip: #{NETWORK_PREFIX}.100
         flannel-iface: eth1
@@ -48,6 +49,7 @@ def provision(vm, role, role_num, node_num)
       k3s.config_mode = '0644' # side-step https://github.com/k3s-io/k3s/issues/4321
       k3s.config = <<~YAML
         server: "https://#{NETWORK_PREFIX}.100:6443"
+        debug: true
         token: vagrant
         node-external-ip: #{node_ip}
         flannel-iface: eth1

tests/e2e/startup/startup_test.go

@@ -42,11 +42,11 @@ func StartK3sCluster(nodes []e2e.VagrantNode, serverYAML string, agentYAML strin
 		var resetCmd string
 		var startCmd string
 		if strings.Contains(node.String(), "server") {
-			resetCmd = "head -n 3 /etc/rancher/k3s/config.yaml > /tmp/config.yaml && sudo mv /tmp/config.yaml /etc/rancher/k3s/config.yaml"
+			resetCmd = "head -n 4 /etc/rancher/k3s/config.yaml > /tmp/config.yaml && sudo mv /tmp/config.yaml /etc/rancher/k3s/config.yaml"
 			yamlCmd = fmt.Sprintf("echo '%s' >> /etc/rancher/k3s/config.yaml", serverYAML)
 			startCmd = "systemctl start k3s"
 		} else {
-			resetCmd = "head -n 4 /etc/rancher/k3s/config.yaml > /tmp/config.yaml && sudo mv /tmp/config.yaml /etc/rancher/k3s/config.yaml"
+			resetCmd = "head -n 5 /etc/rancher/k3s/config.yaml > /tmp/config.yaml && sudo mv /tmp/config.yaml /etc/rancher/k3s/config.yaml"
 			yamlCmd = fmt.Sprintf("echo '%s' >> /etc/rancher/k3s/config.yaml", agentYAML)
 			startCmd = "systemctl start k3s-agent"
 		}
@@ -68,17 +68,18 @@ func KillK3sCluster(nodes []e2e.VagrantNode) error {
 		if _, err := node.RunCmdOnNode("k3s-killall.sh"); err != nil {
 			return err
 		}
+		if _, err := node.RunCmdOnNode("sh -c 'docker ps -qa | xargs -r docker rm -fv'"); err != nil {
+			return err
+		}
+		if _, err := node.RunCmdOnNode("rm -rf /etc/rancher/k3s/config.yaml.d /var/lib/kubelet/pods /var/lib/rancher/k3s/agent/etc /var/lib/rancher/k3s/agent/containerd /var/lib/rancher/k3s/server/db /var/log/pods /run/k3s /run/flannel"); err != nil {
+			return err
+		}
+		if _, err := node.RunCmdOnNode("systemctl restart containerd docker"); err != nil {
+			return err
+		}
 		if _, err := node.RunCmdOnNode("journalctl --flush --sync --rotate --vacuum-size=1"); err != nil {
 			return err
 		}
-		if _, err := node.RunCmdOnNode("rm -rf /etc/rancher/k3s/config.yaml.d"); err != nil {
-			return err
-		}
-		if strings.Contains(node.String(), "server") {
-			if _, err := node.RunCmdOnNode("rm -rf /var/lib/rancher/k3s/server/db"); err != nil {
-				return err
-			}
-		}
 	}
 	return nil
 }
@@ -206,38 +207,6 @@ var _ = Describe("Various Startup Configurations", Ordered, func() {
 			Expect(err).NotTo(HaveOccurred())
 		})
 	})
-	Context("Verify CRI-Dockerd", func() {
-		It("Starts K3s with no issues", func() {
-			dockerYAML := "docker: true"
-			err := StartK3sCluster(tc.AllNodes(), dockerYAML, dockerYAML)
-			Expect(err).NotTo(HaveOccurred(), e2e.GetVagrantLog(err))
-
-			By("CLUSTER CONFIG")
-			By("OS:" + *nodeOS)
-			By(tc.Status())
-			tc.KubeconfigFile, err = e2e.GenKubeconfigFile(tc.Servers[0].String())
-			Expect(err).NotTo(HaveOccurred())
-		})
-
-		It("Checks node and pod status", func() {
-			By("Fetching node status")
-			Eventually(func() error {
-				return tests.NodesReady(tc.KubeconfigFile, e2e.VagrantSlice(tc.AllNodes()))
-			}, "360s", "5s").Should(Succeed())
-
-			Eventually(func() error {
-				return tests.AllPodsUp(tc.KubeconfigFile)
-			}, "360s", "5s").Should(Succeed())
-			Eventually(func() error {
-				return tests.CheckDefaultDeployments(tc.KubeconfigFile)
-			}, "300s", "10s").Should(Succeed())
-			e2e.DumpPods(tc.KubeconfigFile)
-		})
-		It("Kills the cluster", func() {
-			err := KillK3sCluster(tc.AllNodes())
-			Expect(err).NotTo(HaveOccurred())
-		})
-	})
 	Context("Verify prefer-bundled-bin flag", func() {
 		It("Starts K3s with no issues", func() {
 			preferBundledYAML := "prefer-bundled-bin: true"
@@ -256,7 +225,6 @@ var _ = Describe("Various Startup Configurations", Ordered, func() {
 			Eventually(func() error {
 				return tests.NodesReady(tc.KubeconfigFile, e2e.VagrantSlice(tc.AllNodes()))
 			}, "360s", "5s").Should(Succeed())
-
 			Eventually(func() error {
 				return tests.AllPodsUp(tc.KubeconfigFile)
 			}, "360s", "5s").Should(Succeed())
@@ -288,7 +256,9 @@ var _ = Describe("Various Startup Configurations", Ordered, func() {
 			Eventually(func() error {
 				return tests.NodesReady(tc.KubeconfigFile, e2e.VagrantSlice(tc.Agents))
 			}, "360s", "5s").Should(Succeed())
-
+			Eventually(func() error {
+				return tests.AllPodsUp(tc.KubeconfigFile)
+			}, "360s", "5s").Should(Succeed())
 			Eventually(func() error {
 				return tests.CheckDefaultDeployments(tc.KubeconfigFile)
 			}, "300s", "10s").Should(Succeed())
@@ -389,6 +359,37 @@ var _ = Describe("Various Startup Configurations", Ordered, func() {
 			Expect(err).NotTo(HaveOccurred())
 		})
 	})
+	Context("Verify CRI-Dockerd", func() {
+		It("Starts K3s with no issues", func() {
+			dockerYAML := "docker: true"
+			err := StartK3sCluster(tc.AllNodes(), dockerYAML, dockerYAML)
+			Expect(err).NotTo(HaveOccurred(), e2e.GetVagrantLog(err))
+
+			By("CLUSTER CONFIG")
+			By("OS:" + *nodeOS)
+			By(tc.Status())
+			tc.KubeconfigFile, err = e2e.GenKubeconfigFile(tc.Servers[0].String())
+			Expect(err).NotTo(HaveOccurred())
+		})
+
+		It("Checks node and pod status", func() {
+			By("Fetching node status")
+			Eventually(func() error {
+				return tests.NodesReady(tc.KubeconfigFile, e2e.VagrantSlice(tc.AllNodes()))
+			}, "360s", "5s").Should(Succeed())
+			Eventually(func() error {
+				return tests.AllPodsUp(tc.KubeconfigFile)
+			}, "360s", "5s").Should(Succeed())
+			Eventually(func() error {
+				return tests.CheckDefaultDeployments(tc.KubeconfigFile)
+			}, "300s", "10s").Should(Succeed())
+			e2e.DumpPods(tc.KubeconfigFile)
+		})
+		It("Kills the cluster", func() {
+			err := KillK3sCluster(tc.AllNodes())
+			Expect(err).NotTo(HaveOccurred())
+		})
+	})
 })
 
 var failed bool
@@ -399,7 +400,12 @@ var _ = AfterEach(func() {
 var _ = AfterSuite(func() {
 	if failed {
 		AddReportEntry("config", e2e.GetConfig(tc.AllNodes()))
+		AddReportEntry("pods", e2e.DescribePods(tc.KubeconfigFile))
 		Expect(e2e.SaveJournalLogs(tc.AllNodes())).To(Succeed())
+		Expect(e2e.SaveDocker(tc.AllNodes())).To(Succeed())
+		Expect(e2e.TailPodLogs(50, tc.AllNodes())).To(Succeed())
+		Expect(e2e.SaveNetwork(tc.AllNodes())).To(Succeed())
+		Expect(e2e.SaveKernel(tc.AllNodes())).To(Succeed())
 	} else {
 		Expect(e2e.GetCoverageReport(tc.AllNodes())).To(Succeed())
 	}

tests/e2e/testutils.go

@@ -418,6 +418,11 @@ func GenReport(specReport ginkgo.SpecReport) {
 	fmt.Printf("%s", status)
 }
 
+func (v VagrantNode) TailPodLogs(lines int) (string, error) {
+	cmd := fmt.Sprintf("sh -c 'tail -n %d /var/log/pods/*/*/*'", lines)
+	return v.RunCmdOnNode(cmd)
+}
+
 func (v VagrantNode) GetJournalLogs() (string, error) {
 	cmd := "journalctl -u k3s* --no-pager"
 	return v.RunCmdOnNode(cmd)
@@ -436,6 +441,83 @@ func TailJournalLogs(lines int, nodes []VagrantNode) string {
 	return logs.String()
 }
 
+func SaveDocker(nodes []VagrantNode) error {
+	cmd := "sh -xc 'docker ps -a --no-trunc; docker info; journalctl -u containerd -u docker'"
+	for _, node := range nodes {
+		logs, err := node.RunCmdOnNode(cmd)
+		if err != nil {
+			logs = fmt.Sprintf("** failed to list docker containers and logs for node %s: %v **", node, err)
+		}
+		lf, err := os.Create(node.String() + "-dockerlog.txt")
+		if err != nil {
+			return err
+		}
+		defer lf.Close()
+		if _, err := lf.Write([]byte(logs)); err != nil {
+			return err
+		}
+	}
+	return nil
+}
+
+func SaveKernel(nodes []VagrantNode) error {
+	cmd := "dmesg"
+	for _, node := range nodes {
+		logs, err := node.RunCmdOnNode(cmd)
+		if err != nil {
+			logs = fmt.Sprintf("** failed to read kernel message log for node %s: %v **", node, err)
+		}
+		lf, err := os.Create(node.String() + "-kernlog.txt")
+		if err != nil {
+			return err
+		}
+		defer lf.Close()
+		if _, err := lf.Write([]byte(logs)); err != nil {
+			return err
+		}
+	}
+	return nil
+}
+
+func SaveNetwork(nodes []VagrantNode) error {
+	cmd := "sh -xc 'ip addr show; ip route show; ip neighbor show; iptables-save'"
+	for _, node := range nodes {
+		logs, err := node.RunCmdOnNode(cmd)
+		if err != nil {
+			logs = fmt.Sprintf("** failed to read network config for node %s: %v **", node, err)
+		}
+		lf, err := os.Create(node.String() + "-netlog.txt")
+		if err != nil {
+			return err
+		}
+		defer lf.Close()
+		if _, err := lf.Write([]byte(logs)); err != nil {
+			return err
+		}
+	}
+	return nil
+}
+
+// TailPodLogs saves the pod logs of each node to a <NAME>-podlog.txt file.
+// When used in GHA CI, the logs are uploaded as an artifact on failure.
+func TailPodLogs(lines int, nodes []VagrantNode) error {
+	for _, node := range nodes {
+		logs, err := node.TailPodLogs(lines)
+		if err != nil {
+			logs = fmt.Sprintf("** failed to read pod logs for node %s: %v **", node, err)
+		}
+		lf, err := os.Create(node.String() + "-podlog.txt")
+		if err != nil {
+			return err
+		}
+		defer lf.Close()
+		if _, err := lf.Write([]byte(logs)); err != nil {
+			return err
+		}
+	}
+	return nil
+}
+
 // SaveJournalLogs saves the journal logs of each node to a <NAME>-jlog.txt file.
 // When used in GHA CI, the logs are uploaded as an artifact on failure.
 func SaveJournalLogs(nodes []VagrantNode) error {
@@ -497,11 +579,20 @@ func DumpNodes(kubeConfig string) {
 }
 
 func DumpPods(kubeConfig string) {
-	cmd := "kubectl get pods -o wide --no-headers -A"
+	cmd := "kubectl get pods -o wide --no-headers -A --kubeconfig=" + kubeConfig
 	res, _ := RunCommand(cmd)
 	fmt.Println(strings.TrimSpace(res))
 }
 
+func DescribePods(kubeConfig string) string {
+	cmd := "kubectl describe pod -A --kubeconfig=" + kubeConfig
+	res, err := RunCommand(cmd)
+	if err != nil {
+		return fmt.Sprintf("Failed to describe pods: %v", err)
+	}
+	return res
+}
+
 // RestartCluster restarts the k3s service on each node given
 func RestartCluster(nodes []VagrantNode) error {
 	for _, node := range nodes {

tests/e2e/wasm/wasm_test.go

@@ -123,6 +123,7 @@ var _ = AfterEach(func() {
 var _ = AfterSuite(func() {
 	if failed {
 		Expect(e2e.SaveJournalLogs(tc.AllNodes())).To(Succeed())
+		Expect(e2e.TailPodLogs(50, tc.AllNodes())).To(Succeed())
 	} else {
 		Expect(e2e.GetCoverageReport(tc.AllNodes())).To(Succeed())
 	}