Dumps logs even if test failed

tests/common.go

@@ -13,6 +13,7 @@ const allClustersSnap = "matter-all-clusters-app"
 const chipToolSnap = "chip-tool"
 
 func InstallChipTool(t *testing.T) {
+	start := time.Now()
 
 	// clean
 	utils.SnapRemove(t, chipToolSnap)
@@ -28,6 +29,8 @@ func InstallChipTool(t *testing.T) {
 	}
 	t.Cleanup(func() {
 		utils.SnapRemove(t, chipToolSnap)
+		logs := utils.SnapLogs(t, start, chipToolSnap)
+		utils.WriteLogFile(t, chipToolSnap, logs)
 	})
 
 	// connect interfaces

tests/thread_tests/local.go

@@ -1,7 +1,6 @@
 package thread_tests
 
 import (
-	"fmt"
 	"os"
 	"strings"
 	"testing"
@@ -19,8 +18,11 @@ func setup(t *testing.T) {
 	utils.SnapRemove(t, otbrSnap)
 
 	// Install OTBR
+	otbrInstallTime := time.Now()
 	utils.SnapInstallFromStore(t, otbrSnap, "latest/beta")
 	t.Cleanup(func() {
+		logs := utils.SnapLogs(t, otbrInstallTime, otbrSnap)
+		utils.WriteLogFile(t, otbrSnap, logs)
 		utils.SnapRemove(t, otbrSnap)
 	})
 
@@ -47,16 +49,16 @@ func setup(t *testing.T) {
 	}
 
 	// Start OTBR
-	start := time.Now()
+	otbrStartTime := time.Now()
 	utils.SnapStart(t, otbrSnap)
-	waitForLogMessage(t, otbrSnap, "Start Thread Border Agent: OK", start)
+	utils.WaitForLogMessage(t, otbrSnap, "Start Thread Border Agent: OK", otbrStartTime)
 
 	// Form Thread network
 	utils.Exec(t, "sudo "+OTCTL+" dataset init new")
 	utils.Exec(t, "sudo "+OTCTL+" dataset commit active")
 	utils.Exec(t, "sudo "+OTCTL+" ifconfig up")
 	utils.Exec(t, "sudo "+OTCTL+" thread start")
-	utils.WaitForLogMessage(t, otbrSnap, "Thread Network", start)
+	utils.WaitForLogMessage(t, otbrSnap, "Thread Network", otbrStartTime)
 }
 
 func getActiveDataset(t *testing.T) string {
@@ -65,26 +67,3 @@ func getActiveDataset(t *testing.T) string {
 
 	return trimmedActiveDataset
 }
-
-// TODO: update the library function to print the tail before failing:
-// https://github.com/canonical/matter-snap-testing/blob/abae29ac5e865f0c5208350bdab63cecb3bdcc5a/utils/config.go#L54-L69
-func waitForLogMessage(t *testing.T, snap, expectedLog string, since time.Time) {
-	const maxRetry = 10
-
-	for i := 1; i <= maxRetry; i++ {
-		time.Sleep(1 * time.Second)
-		t.Logf("Retry %d/%d: Waiting for expected content in logs: %s", i, maxRetry, expectedLog)
-
-		logs := utils.SnapLogs(t, since, snap)
-		if strings.Contains(logs, expectedLog) {
-			t.Logf("Found expected content in logs: %s", expectedLog)
-			return
-		}
-	}
-
-	t.Logf("Time out: reached max %d retries.", maxRetry)
-	stdout, _, _ := utils.Exec(t,
-		fmt.Sprintf("sudo journalctl --lines=10 --no-pager --unit=snap.\"%s\".otbr-agent --priority=notice", snap))
-	t.Log(stdout)
-	t.FailNow()
-}

tests/thread_tests/remote.go

@@ -8,6 +8,7 @@ import (
 	"testing"
 	"time"
 
+	"github.com/canonical/matter-snap-testing/utils"
 	"golang.org/x/crypto/ssh"
 )
 
@@ -82,13 +83,13 @@ func connectSSH(t *testing.T) {
 }
 
 func remote_deployOTBRAgent(t *testing.T) {
+	start := time.Now().UTC()
 
 	t.Cleanup(func() {
+		dumpRemoteLogs(t, "openthread-border-router", start)
 		remote_exec(t, "sudo snap remove --purge openthread-border-router")
 	})
 
-	start := time.Now().UTC()
-
 	commands := []string{
 		"sudo snap remove --purge openthread-border-router",
 		"sudo snap install openthread-border-router --channel=latest/beta",
@@ -111,13 +112,13 @@ func remote_deployOTBRAgent(t *testing.T) {
 }
 
 func remote_deployAllClustersApp(t *testing.T) {
+	start := time.Now().UTC()
 
 	t.Cleanup(func() {
+		dumpRemoteLogs(t, "matter-all-clusters-app", start)
 		remote_exec(t, "sudo snap remove --purge matter-all-clusters-app")
 	})
 
-	start := time.Now().UTC()
-
 	commands := []string{
 		// "sudo apt install -y bluez",
 		"sudo snap remove --purge matter-all-clusters-app",
@@ -191,3 +192,9 @@ func remote_waitForLogMessage(t *testing.T, snap string, expectedLog string, sta
 	t.Log(remote_exec(t, "journalctl --no-pager --lines=10 --unit=snap.openthread-border-router.otbr-agent --priority=notice"))
 	t.FailNow()
 }
+
+func dumpRemoteLogs(t *testing.T, label string, start time.Time) error {
+	command := fmt.Sprintf("sudo journalctl --utc --since \"%s\" --no-pager | grep \"%s\"|| true", start.UTC().Format("2006-01-02 15:04:05"), label)
+	logs := remote_exec(t, command)
+	return utils.WriteLogFile(t, "remote-"+label, logs)
+}

tests/upgrade_test.go

@@ -14,11 +14,12 @@ func TestUpgrade(t *testing.T) {
 	start := time.Now()
 
 	t.Cleanup(func() {
+		utils.SnapDumpLogs(t, start, allClustersSnap)
+		utils.SnapDumpLogs(t, start, chipToolSnap)
+
 		// Remove snaps, ignoring errors during removal
 		utils.SnapRemove(nil, allClustersSnap)
 		utils.SnapRemove(nil, chipToolSnap)
-
-		utils.SnapDumpLogs(t, start, allClustersSnap)
 	})
 
 	// Start clean

tests/wifi_test.go

@@ -17,8 +17,8 @@ func TestAllClustersAppWiFi(t *testing.T) {
 	utils.SnapRemove(t, allClustersSnap)
 
 	t.Cleanup(func() {
-		utils.SnapRemove(t, allClustersSnap)
 		utils.SnapDumpLogs(t, start, allClustersSnap)
+		utils.SnapRemove(t, allClustersSnap)
 	})
 
 	// Install all clusters app