From 548841623ab8bfce44ed012252d6df18839d9f5e Mon Sep 17 00:00:00 2001 From: Farshid Tavakolizadeh Date: Fri, 16 Feb 2024 16:06:05 +0200 Subject: [PATCH] Refactor tests, improve logging (#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 | 6 ++- tests/go.sum | 8 +-- tests/snap_test.go | 121 ++++++++++++++++++++------------------------- 3 files changed, 61 insertions(+), 74 deletions(-) diff --git a/tests/go.mod b/tests/go.mod index 9a46d2b..89e656e 100644 --- a/tests/go.mod +++ b/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 ) diff --git a/tests/go.sum b/tests/go.sum index 0dd145f..498734b 100644 --- a/tests/go.sum +++ b/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= diff --git a/tests/snap_test.go b/tests/snap_test.go index 960efce..b8d5cd6 100644 --- a/tests/snap_test.go +++ b/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 -}