From 35beda2d1d8dfaa4db41558606c5388e83d74af0 Mon Sep 17 00:00:00 2001 From: JP Meijers Date: Tue, 27 Aug 2024 15:31:49 +0200 Subject: [PATCH 1/3] Dumps logs in cleanup after uninstall --- tests/common.go | 3 +++ tests/thread_tests/local.go | 33 ++++++--------------------------- tests/thread_tests/remote.go | 15 +++++++++++---- 3 files changed, 20 insertions(+), 31 deletions(-) diff --git a/tests/common.go b/tests/common.go index 45b018f..aedaf8e 100644 --- a/tests/common.go +++ b/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 diff --git a/tests/thread_tests/local.go b/tests/thread_tests/local.go index 0607a05..08ae7c3 100644 --- a/tests/thread_tests/local.go +++ b/tests/thread_tests/local.go @@ -1,7 +1,6 @@ package thread_tests import ( - "fmt" "os" "strings" "testing" @@ -19,9 +18,12 @@ func setup(t *testing.T) { utils.SnapRemove(t, otbrSnap) // Install OTBR + otbrInstallTime := time.Now() utils.SnapInstallFromStore(t, otbrSnap, "latest/beta") t.Cleanup(func() { utils.SnapRemove(t, otbrSnap) + logs := utils.SnapLogs(t, otbrInstallTime, otbrSnap) + utils.WriteLogFile(t, otbrSnap, logs) }) // Connect interfaces @@ -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() -} diff --git a/tests/thread_tests/remote.go b/tests/thread_tests/remote.go index 9d0a5bd..ba3f039 100644 --- a/tests/thread_tests/remote.go +++ b/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() { remote_exec(t, "sudo snap remove --purge openthread-border-router") + remoteDumpLogs(t, "openthread-border-router", start) }) - 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() { remote_exec(t, "sudo snap remove --purge matter-all-clusters-app") + remoteDumpLogs(t, "matter-all-clusters-app", start) }) - 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 remoteDumpLogs(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) +} From 53d9787a3b9c2a7a0ddec283683ab57a1b76539f Mon Sep 17 00:00:00 2001 From: JP Meijers Date: Tue, 27 Aug 2024 16:55:52 +0200 Subject: [PATCH 2/3] Rename function to be more descriptive --- tests/thread_tests/remote.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tests/thread_tests/remote.go b/tests/thread_tests/remote.go index ba3f039..fce726e 100644 --- a/tests/thread_tests/remote.go +++ b/tests/thread_tests/remote.go @@ -87,7 +87,7 @@ func remote_deployOTBRAgent(t *testing.T) { t.Cleanup(func() { remote_exec(t, "sudo snap remove --purge openthread-border-router") - remoteDumpLogs(t, "openthread-border-router", start) + dumpRemoteLogs(t, "openthread-border-router", start) }) commands := []string{ @@ -116,7 +116,7 @@ func remote_deployAllClustersApp(t *testing.T) { t.Cleanup(func() { remote_exec(t, "sudo snap remove --purge matter-all-clusters-app") - remoteDumpLogs(t, "matter-all-clusters-app", start) + dumpRemoteLogs(t, "matter-all-clusters-app", start) }) commands := []string{ @@ -193,7 +193,7 @@ func remote_waitForLogMessage(t *testing.T, snap string, expectedLog string, sta t.FailNow() } -func remoteDumpLogs(t *testing.T, label string, start time.Time) error { +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) From f6175a49d080792362d9c30af19582391fe81af7 Mon Sep 17 00:00:00 2001 From: JP Meijers Date: Wed, 28 Aug 2024 12:47:03 +0200 Subject: [PATCH 3/3] Dump logs before removal --- tests/thread_tests/local.go | 2 +- tests/thread_tests/remote.go | 4 ++-- tests/upgrade_test.go | 5 +++-- tests/wifi_test.go | 2 +- 4 files changed, 7 insertions(+), 6 deletions(-) diff --git a/tests/thread_tests/local.go b/tests/thread_tests/local.go index 08ae7c3..4f348db 100644 --- a/tests/thread_tests/local.go +++ b/tests/thread_tests/local.go @@ -21,9 +21,9 @@ func setup(t *testing.T) { otbrInstallTime := time.Now() utils.SnapInstallFromStore(t, otbrSnap, "latest/beta") t.Cleanup(func() { - utils.SnapRemove(t, otbrSnap) logs := utils.SnapLogs(t, otbrInstallTime, otbrSnap) utils.WriteLogFile(t, otbrSnap, logs) + utils.SnapRemove(t, otbrSnap) }) // Connect interfaces diff --git a/tests/thread_tests/remote.go b/tests/thread_tests/remote.go index fce726e..a553dd1 100644 --- a/tests/thread_tests/remote.go +++ b/tests/thread_tests/remote.go @@ -86,8 +86,8 @@ func remote_deployOTBRAgent(t *testing.T) { start := time.Now().UTC() t.Cleanup(func() { - remote_exec(t, "sudo snap remove --purge openthread-border-router") dumpRemoteLogs(t, "openthread-border-router", start) + remote_exec(t, "sudo snap remove --purge openthread-border-router") }) commands := []string{ @@ -115,8 +115,8 @@ func remote_deployAllClustersApp(t *testing.T) { start := time.Now().UTC() t.Cleanup(func() { - remote_exec(t, "sudo snap remove --purge matter-all-clusters-app") dumpRemoteLogs(t, "matter-all-clusters-app", start) + remote_exec(t, "sudo snap remove --purge matter-all-clusters-app") }) commands := []string{ diff --git a/tests/upgrade_test.go b/tests/upgrade_test.go index 25d29ff..7cb1b2d 100644 --- a/tests/upgrade_test.go +++ b/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 diff --git a/tests/wifi_test.go b/tests/wifi_test.go index 24480f4..0ae0ea1 100644 --- a/tests/wifi_test.go +++ b/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