Fix tests by changing log assertions (#69)

* Fix time reference for log queries

* Move "Upgrade snap" to a subtest so it doesn't run when a previous subtest fails in failfast mode

* Set unique names for subtest logs to avoid overriding others

* Update reference log message for the assertions - the SDK has changed the log prefixes

* Remove obsolete log dump for chip tool, as it has no service that writes logs to the journal

* The CHIP logs are now buffered. Change the assertions to seek a reference that is produced prior to the buffering of request handling debug info.

* Comment out bluetooth setup on remote device in thread tests as bluetooth isn't needed.

tests/common.go

@@ -1,9 +1,13 @@
 package tests
 
 import (
+	"os"
+	"strings"
 	"testing"
+	"time"
 
 	"github.com/canonical/matter-snap-testing/utils"
+	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
 
@@ -33,3 +37,16 @@ func InstallChipTool(t *testing.T) {
 	utils.SnapConnect(t, chipToolSnap+":bluez", "")
 	utils.SnapConnect(t, chipToolSnap+":process-control", "")
 }
+
+func writeLogFile(t *testing.T, label string, b []byte) {
+	assert.NoError(t,
+		os.WriteFile(strings.ReplaceAll(t.Name(), "/", "-")+"-"+label+".log", b, 0644),
+	)
+}
+
+func waitForOnOffHandlingByAllClustersApp(t *testing.T, start time.Time) {
+	// 0x6 is the Matter Cluster ID for on-off
+	// Using cluster ID here because of a buffering issue in the log stream:
+	// https://github.com/canonical/chip-tool-snap/pull/69#issuecomment-2207189962
+	utils.WaitForLogMessage(t, allClustersSnap, "ClusterId = 0x6", start)
+}

tests/thread_tests/remote.go

@@ -119,12 +119,12 @@ func remote_deployAllClustersApp(t *testing.T) {
 	start := time.Now().UTC()
 
 	commands := []string{
-		"sudo apt install bluez",
+		// "sudo apt install -y bluez",
 		"sudo snap remove --purge matter-all-clusters-app",
 		"sudo snap install matter-all-clusters-app --edge",
 		"sudo snap set matter-all-clusters-app args='--thread'",
 		"sudo snap connect matter-all-clusters-app:avahi-control",
-		"sudo snap connect matter-all-clusters-app:bluez",
+		// "sudo snap connect matter-all-clusters-app:bluez",
 		"sudo snap connect matter-all-clusters-app:otbr-dbus-wpan0 openthread-border-router:dbus-wpan0",
 		"sudo snap start matter-all-clusters-app",
 	}

tests/thread_tests/thread_test.go

@@ -30,7 +30,10 @@ func TestAllClustersAppThread(t *testing.T) {
 			os.WriteFile("chip-tool-thread-onoff.log", []byte(stdout), 0644),
 		)
 
-		remote_waitForLogMessage(t, "matter-all-clusters-app", "CHIP:ZCL: Toggle ep1 on/off", start)
+		// 0x6 is the Matter Cluster ID for on-off
+		// Using cluster ID here because of a buffering issue in the log stream:
+		// https://github.com/canonical/chip-tool-snap/pull/69#issuecomment-2209530275
+		remote_waitForLogMessage(t, "matter-all-clusters-app", "ClusterId = 0x6", start)
 	})
 
 }

tests/upgrade_test.go

@@ -1,23 +1,21 @@
 package tests
 
 import (
-	"github.com/canonical/matter-snap-testing/utils"
-	"github.com/stretchr/testify/assert"
 	"log"
-	"os"
 	"testing"
 	"time"
+
+	"github.com/canonical/matter-snap-testing/utils"
 )
 
 func TestUpgrade(t *testing.T) {
 	start := time.Now()
 
-	// Remove snaps and logs at end of test, even if it failed
 	t.Cleanup(func() {
 		utils.SnapRemove(nil, allClustersSnap)
 		utils.SnapDumpLogs(nil, start, allClustersSnap)
+
 		utils.SnapRemove(nil, chipToolSnap)
-		utils.SnapDumpLogs(nil, start, chipToolSnap)
 	})
 
 	// Start clean
@@ -45,49 +43,41 @@ func TestUpgrade(t *testing.T) {
 	utils.WaitForLogMessage(t,
 		allClustersSnap, "CHIP minimal mDNS started advertising", start)
 
-	// Pair device
 	t.Run("Commission", func(t *testing.T) {
 		stdout, _, _ := utils.Exec(t, "sudo chip-tool pairing onnetwork 110 20202021 2>&1")
-		assert.NoError(t,
-			os.WriteFile("chip-tool-pairing.log", []byte(stdout), 0644),
-		)
+		writeLogFile(t, "chip-tool-pairing", []byte(stdout))
 	})
 
-	// Control device
-	t.Run("Control with stable snap", func(t *testing.T) {
+	t.Run("Control before upgrade", func(t *testing.T) {
 		snapVersion := utils.SnapVersion(t, chipToolSnap)
 		snapRevision := utils.SnapRevision(t, chipToolSnap)
 		log.Printf("%s installed version %s build %s\n", chipToolSnap, snapVersion, snapRevision)
 
-		stdout, _, _ := utils.Exec(t, "sudo chip-tool onoff toggle 110 1 2>&1")
-		assert.NoError(t,
-			os.WriteFile("chip-tool-onoff.log", []byte(stdout), 0644),
-		)
+		start := time.Now()
+		stdout, _, _ := utils.Exec(t, "sudo chip-tool onoff on 110 1 2>&1")
+		writeLogFile(t, "chip-tool-onoff", []byte(stdout))
 
-		utils.WaitForLogMessage(t,
-			allClustersSnap, "CHIP:ZCL: Toggle ep1 on/off", start)
+		waitForOnOffHandlingByAllClustersApp(t, start)
 	})
 
-	// Upgrade chip-tool to local snap or edge
-	if utils.LocalServiceSnap() {
-		utils.SnapInstallFromFile(t, utils.LocalServiceSnapPath)
-	} else {
-		utils.SnapRefresh(t, chipToolSnap, "latest/edge")
-	}
+	t.Run("Upgrade snap", func(t *testing.T) {
+		if utils.LocalServiceSnap() {
+			utils.SnapInstallFromFile(t, utils.LocalServiceSnapPath)
+		} else {
+			utils.SnapRefresh(t, chipToolSnap, "latest/edge")
+		}
+	})
 
-	// Control device again
 	t.Run("Control upgraded snap", func(t *testing.T) {
 		snapVersion := utils.SnapVersion(t, chipToolSnap)
 		snapRevision := utils.SnapRevision(t, chipToolSnap)
 		log.Printf("%s installed version %s build %s\n", chipToolSnap, snapVersion, snapRevision)
 
-		stdout, _, _ := utils.Exec(t, "sudo chip-tool onoff toggle 110 1 2>&1")
-		assert.NoError(t,
-			os.WriteFile("chip-tool-onoff.log", []byte(stdout), 0644),
-		)
+		start := time.Now()
+		stdout, _, _ := utils.Exec(t, "sudo chip-tool onoff off 110 1 2>&1")
+		writeLogFile(t, "chip-tool-onoff", []byte(stdout))
 
-		utils.WaitForLogMessage(t,
-			allClustersSnap, "CHIP:ZCL: Toggle ep1 on/off", start)
+		waitForOnOffHandlingByAllClustersApp(t, start)
 	})
 
 }

tests/wifi_test.go

@@ -1,12 +1,10 @@
 package tests
 
 import (
-	"os"
 	"testing"
 	"time"
 
 	"github.com/canonical/matter-snap-testing/utils"
-	"github.com/stretchr/testify/assert"
 )
 
 func TestAllClustersAppWiFi(t *testing.T) {
@@ -19,11 +17,11 @@ func TestAllClustersAppWiFi(t *testing.T) {
 
 	t.Cleanup(func() {
 		utils.SnapRemove(t, allClustersSnap)
-		utils.SnapDumpLogs(nil, start, allClustersSnap)
+		utils.SnapDumpLogs(t, start, allClustersSnap)
 	})
 
 	// Install all clusters app
-	utils.SnapInstallFromStore(t, allClustersSnap, utils.ServiceChannel)
+	utils.SnapInstallFromStore(t, allClustersSnap, "latest/edge")
 
 	// Setup all clusters app
 	utils.SnapSet(t, allClustersSnap, "args", "--wifi")
@@ -37,19 +35,14 @@ func TestAllClustersAppWiFi(t *testing.T) {
 
 	t.Run("Commission", func(t *testing.T) {
 		stdout, _, _ := utils.Exec(t, "sudo chip-tool pairing onnetwork 110 20202021 2>&1")
-		assert.NoError(t,
-			os.WriteFile("chip-tool-pairing.log", []byte(stdout), 0644),
-		)
+		writeLogFile(t, "chip-tool-pairing", []byte(stdout))
 	})
 
 	t.Run("Control", func(t *testing.T) {
 		stdout, _, _ := utils.Exec(t, "sudo chip-tool onoff toggle 110 1 2>&1")
-		assert.NoError(t,
-			os.WriteFile("chip-tool-onoff.log", []byte(stdout), 0644),
-		)
+		writeLogFile(t, "chip-tool-toggle", []byte(stdout))
 
-		utils.WaitForLogMessage(t,
-			allClustersSnap, "CHIP:ZCL: Toggle ep1 on/off", start)
+		waitForOnOffHandlingByAllClustersApp(t, start)
 	})
 
 }