Refactor tests, improve logging (canonical#45)

* Add command logging

* Cleanup existing logs, improve vars

* Refactor app start code

* Switch to v1.0.0-beta.1 matter-snap-testing

* Remove obsolete code

tests/go.mod

@@ -2,12 +2,14 @@ module chip-tool-snap-tests
 
 go 1.21.6
 
-require github.com/canonical/matter-snap-testing v1.0.0-beta
+require (
+	github.com/canonical/matter-snap-testing v1.0.0-beta.1
+	github.com/stretchr/testify v1.8.4
+)
 
 require (
 	github.com/davecgh/go-spew v1.1.1 // indirect
 	github.com/kr/text v0.2.0 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
-	github.com/stretchr/testify v1.8.3 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect
 )

tests/go.sum

@@ -1,5 +1,5 @@
-github.com/canonical/matter-snap-testing v1.0.0-beta h1:wEVJduO9Crz8gfp/SzGL9OkAmJmNahC3yQ/2o7s9J5c=
-github.com/canonical/matter-snap-testing v1.0.0-beta/go.mod h1:Ku1D0Dl99nWbxK/CGPfjOSBmIZ09NqkO14p1gjwTg5o=
+github.com/canonical/matter-snap-testing v1.0.0-beta.1 h1:obxh5jYRWgCw6QNax4+aY571h+q/zcPZBOP64gwd56E=
+github.com/canonical/matter-snap-testing v1.0.0-beta.1/go.mod h1:800wP9+ux8DW9Xr9QvlIdxFHlu85mqlhvlA2JO20aeQ=
 github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
@@ -9,8 +9,8 @@ github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY=
 github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
-github.com/stretchr/testify v1.8.3 h1:RP3t2pwF7cMEbC1dqtB6poj3niw/9gnV4Cjg5oW5gtY=
-github.com/stretchr/testify v1.8.3/go.mod h1:sz/lmYIOXD/1dqDmKjjqLyZ2RngseejIcXlSw2iwfAo=
+github.com/stretchr/testify v1.8.4 h1:CcVxjf3Q8PM0mHUKJCdn+eZZtm5yQwehR5yeSVQQcUk=
+github.com/stretchr/testify v1.8.4/go.mod h1:sz/lmYIOXD/1dqDmKjjqLyZ2RngseejIcXlSw2iwfAo=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY=
 gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=

tests/snap_test.go

@@ -1,18 +1,22 @@
 package tests
 
 import (
+	"context"
 	"log"
 	"os"
 	"os/exec"
-	"path/filepath"
 	"strings"
 	"testing"
 	"time"
 
 	"github.com/canonical/matter-snap-testing/utils"
+	"github.com/stretchr/testify/assert"
 )
 
-var start = time.Now()
+const (
+	allClustersAppBin = "bin/chip-all-clusters-minimal-app-commit-1536ca2"
+	allClustersAppLog = "chip-all-clusters-minimal-app.log"
+)
 
 func TestMain(m *testing.M) {
 	teardown, err := setup()
@@ -26,64 +30,30 @@ func TestMain(m *testing.M) {
 	os.Exit(code)
 }
 
-func TestMatterDeviceOperations(t *testing.T) {
-	const (
-		chipAllClusterMinimalAppFile = "bin/chip-all-clusters-minimal-app-commit-1536ca2"
-		chipAllClusterMinimalAppLog  = "chip-all-clusters-minimal-app.log"
-	)
-
-	// Setup: remove exisiting log files
-	if err := os.Remove("./" + chipAllClusterMinimalAppLog); err != nil && !os.IsNotExist(err) {
-		t.Fatalf("Error deleting log file: %s\n", err)
-	}
-	if err := os.Remove("./chip-tool.log"); err != nil && !os.IsNotExist(err) {
-		t.Fatalf("Error deleting log file: %s\n", err)
-	}
-
-	// Setup: run and log chip-all-clusters-minimal-app in the background
-	logFile, err := os.Create(chipAllClusterMinimalAppLog)
-	if err != nil {
-		t.Fatalf("Error creating log file: %s\n", err)
-	}
-
-	cmd := exec.Command("./" + chipAllClusterMinimalAppFile)
-	cmd.Stdout = logFile
-	cmd.Stderr = logFile
-
-	err = cmd.Start()
-	if err != nil {
-		t.Fatalf("Error starting application: %s\n", err)
-	}
+func TestAllClustersApp(t *testing.T) {
+	startAllClustersApp(t)
 
-	t.Cleanup(func() {
-		matches, err := filepath.Glob("/tmp/chip_*")
-		if err != nil {
-			t.Fatalf("Error finding tmp chip files: %s\n", err)
-		}
-
-		for _, match := range matches {
-			if err := os.Remove(match); err != nil {
-				t.Fatalf("Error removing tmp chip file %s: %s\n", match, err)
-			}
-		}
-
-		if err := cmd.Process.Kill(); err != nil {
-			t.Fatalf("Error killing process: %s\n", err)
-		}
-
-		if logFile != nil {
-			logFile.Close()
-		}
-	})
+	// wait for startup
+	waitForLogMessage(t,
+		allClustersAppLog, "CHIP minimal mDNS started advertising")
 
 	t.Run("Commission", func(t *testing.T) {
-		utils.Exec(t, "sudo chip-tool pairing onnetwork 110 20202021")
+		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),
+		)
 	})
 
 	t.Run("Control", func(t *testing.T) {
-		utils.Exec(t, "sudo chip-tool onoff toggle 110 1")
-		waitForAppMessage(t, "./"+chipAllClusterMinimalAppLog, "CHIP:ZCL: Toggle ep1 on/off", start)
+		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),
+		)
+
+		waitForLogMessage(t,
+			allClustersAppLog, "CHIP:ZCL: Toggle ep1 on/off")
 	})
+
 }
 
 func setup() (teardown func(), err error) {
@@ -96,7 +66,6 @@ func setup() (teardown func(), err error) {
 
 	teardown = func() {
 		log.Println("[TEARDOWN]")
-		utils.SnapDumpLogs(nil, start, chipToolSnap)
 
 		log.Println("Removing installed snap:", !utils.SkipTeardownRemoval)
 		if !utils.SkipTeardownRemoval {
@@ -122,32 +91,48 @@ func setup() (teardown func(), err error) {
 	return
 }
 
-func waitForAppMessage(t *testing.T, appLogPath, expectedLog string, since time.Time) {
+func startAllClustersApp(t *testing.T) {
+	// remove existing temp files
+	utils.Exec(t, "rm -fr /tmp/chip_*")
+
+	logFile, err := os.Create(allClustersAppLog)
+	if err != nil {
+		t.Fatalf("Error creating log file: %s", err)
+	}
+
+	ctx, cancel := context.WithCancel(context.Background())
+	t.Cleanup(cancel)
+
+	cmd := exec.CommandContext(ctx, allClustersAppBin)
+	cmd.Stdout = logFile
+	cmd.Stderr = logFile
+
+	if err := cmd.Start(); err != nil {
+		t.Fatalf("Error starting application: %s", err)
+	}
+
+	t.Cleanup(func() {
+		utils.Exec(t, "rm -f /tmp/chip_*")
+	})
+}
+
+func waitForLogMessage(t *testing.T, logPath, expectedMsg string) {
 	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)
+		t.Logf("Retry %d/%d: Find log message: '%s'", i, maxRetry, expectedMsg)
 
-		logs, err := readLogFile(appLogPath)
+		logs, err := os.ReadFile(logPath)
 		if err != nil {
 			t.Fatalf("Error reading log file: %s\n", err)
-			continue
 		}
 
-		if strings.Contains(logs, expectedLog) {
-			t.Logf("Found expected content in logs: %s", expectedLog)
+		if strings.Contains(string(logs), expectedMsg) {
+			t.Logf("Found log message: '%s'", expectedMsg)
 			return
 		}
 	}
 
 	t.Fatalf("Time out: reached max %d retries.", maxRetry)
 }
-
-func readLogFile(filePath string) (string, error) {
-	text, err := os.ReadFile(filePath)
-	if err != nil {
-		return "", err
-	}
-	return string(text), nil
-}