From 98bf866e383791d0d31798830ac86797250729a3 Mon Sep 17 00:00:00 2001 From: Kegan Dougal Date: Tue, 14 Nov 2023 17:53:15 +0000 Subject: [PATCH] Log to file and upload as artifacts; better colours on failures --- .github/workflows/tests.yaml | 8 +++++++ README.md | 2 ++ internal/api/client.go | 17 +++++++++++++++ internal/api/js.go | 42 +++++++++++++++++++++++++----------- internal/api/rust.go | 10 ++++----- tests/main_test.go | 2 ++ 6 files changed, 63 insertions(+), 18 deletions(-) diff --git a/.github/workflows/tests.yaml b/.github/workflows/tests.yaml index bd68426..389d02f 100644 --- a/.github/workflows/tests.yaml +++ b/.github/workflows/tests.yaml @@ -106,3 +106,11 @@ jobs: COMPLEMENT_SHARE_ENV_PREFIX: PASS_ PASS_SYNAPSE_COMPLEMENT_DATABASE: sqlite DOCKER_BUILDKIT: 1 + + - name: Upload logs + uses: actions/upload-artifact@v2 + with: + name: Logs - ${{ job.status }} + path: | + ./tests/rust_sdk_logs* + ./tests/js_sdk.log diff --git a/README.md b/README.md index 1376e9c..d11c182 100644 --- a/README.md +++ b/README.md @@ -24,6 +24,8 @@ COMPLEMENT_BASE_IMAGE=homeserver:latest go test -v ./tests TODO: consider checking in working builds so you can git clone and run. Git LFS for `libmatrix_sdk_ffi.so` given it's 60MB? +If you get failing tests, JS SDK logs to file as does Rust SDK in `./tests`, which are uploaded to GHA as artifacts. You can then grep for the test name to find the right place in the file e.g `grep 'TestAliceBobEncryptionWorks/js|js' tests/js_sdk.log`. + #### Environment Variables - `COMPLEMENT_CRYPTO_TEST_CLIENT_MATRIX` : Comma separated clients to run. Default: `jj,jr,rj,rr` diff --git a/internal/api/client.go b/internal/api/client.go index fde047b..6204574 100644 --- a/internal/api/client.go +++ b/internal/api/client.go @@ -143,3 +143,20 @@ func CheckEventHasMembership(target, membership string) func(e Event) bool { return e.Membership == membership && e.Target == target } } + +const ansiRedForeground = "\x1b[31m" +const ansiResetForeground = "\x1b[39m" + +// errorf is a wrapper around t.Errorf which prints the failing error message in red. +func errorf(t *testing.T, format string, args ...any) { + t.Helper() + format = ansiRedForeground + format + ansiResetForeground + t.Errorf(format, args...) +} + +// fatalf is a wrapper around t.Fatalf which prints the failing error message in red. +func fatalf(t *testing.T, format string, args ...any) { + t.Helper() + format = ansiRedForeground + format + ansiResetForeground + t.Fatalf(format, args...) +} diff --git a/internal/api/js.go b/internal/api/js.go index a1b488d..a7d87ac 100644 --- a/internal/api/js.go +++ b/internal/api/js.go @@ -8,6 +8,7 @@ import ( "io/fs" "net" "net/http" + "os" "strconv" "strings" "sync" @@ -26,6 +27,29 @@ const CONSOLE_LOG_CONTROL_STRING = "CC:" // for "complement-crypto" //go:embed dist var jsSDKDistDirectory embed.FS +var logFile *os.File + +func SetupJSLogs(filename string) { + var err error + logFile, err = os.OpenFile(filename, os.O_RDWR|os.O_CREATE, 0666) + if err != nil { + panic(err) + } + logFile.Truncate(0) +} + +func WriteJSLogs() { + logFile.Close() +} + +func writeToLog(s string, args ...interface{}) { + str := fmt.Sprintf(s, args...) + _, err := logFile.WriteString(time.Now().Format("15:04:05.000000Z07:00") + " " + str) + if err != nil { + panic(err) + } +} + type JSClient struct { ctx context.Context cancel func() @@ -54,7 +78,7 @@ func NewJSClient(t *testing.T, opts ClientCreationOpts) (Client, error) { s = string(arg.Value) } // TODO: debug mode only? - colorify("[%s] console.log %s\n", opts.UserID, s) + writeToLog("[%s] console.log %s\n", opts.UserID, s) if strings.HasPrefix(s, CONSOLE_LOG_CONTROL_STRING) { val := strings.TrimPrefix(s, CONSOLE_LOG_CONTROL_STRING) @@ -62,7 +86,7 @@ func NewJSClient(t *testing.T, opts ClientCreationOpts) (Client, error) { segs := strings.Split(val, "||") var ev JSEvent if err := json.Unmarshal([]byte(segs[1]), &ev); err != nil { - colorify("[%s] failed to unmarshal event '%s' into Go %s\n", opts.UserID, segs[1], err) + writeToLog("[%s] failed to unmarshal event '%s' into Go %s\n", opts.UserID, segs[1], err) continue } for _, l := range jsc.listeners { @@ -190,7 +214,7 @@ func (c *JSClient) StartSyncing(t *testing.T) (stopSyncing func()) { chrome.AwaitExecute(t, c.ctx, `window.__client.startClient({});`) select { case <-time.After(5 * time.Second): - t.Fatalf("[%s](js) took >5s to StartSyncing", c.userID) + fatalf(t, "[%s](js) took >5s to StartSyncing", c.userID) case <-ch: } cancel() @@ -286,25 +310,17 @@ func (w *jsTimelineWaiter) Wait(t *testing.T, s time.Duration) { for { timeLeft := s - time.Since(start) if timeLeft <= 0 { - t.Fatalf("%s: Wait[%s]: timed out", w.client.userID, w.roomID) + fatalf(t, "%s: Wait[%s]: timed out", w.client.userID, w.roomID) } select { case <-time.After(timeLeft): - t.Fatalf("%s: Wait[%s]: timed out", w.client.userID, w.roomID) + fatalf(t, "%s: Wait[%s]: timed out", w.client.userID, w.roomID) case <-updates: return } } } -const ansiYellowForeground = "\x1b[33m" -const ansiRedForeground = "\x1b[31m" -const ansiResetForeground = "\x1b[39m" - -func colorify(format string, args ...any) { - format = ansiYellowForeground + time.Now().Format(time.RFC3339) + " " + format + ansiResetForeground - fmt.Printf(format, args...) -} func colorifyError(format string, args ...any) { format = ansiRedForeground + time.Now().Format(time.RFC3339) + " " + format + ansiResetForeground fmt.Printf(format, args...) diff --git a/internal/api/rust.go b/internal/api/rust.go index 14fb2a1..c7dfcdd 100644 --- a/internal/api/rust.go +++ b/internal/api/rust.go @@ -17,7 +17,7 @@ func init() { Filter: "debug", WriteToFiles: &matrix_sdk_ffi.TracingFileConfiguration{ Path: ".", - FilePrefix: "rust_sdk", + FilePrefix: "rust_sdk_logs", }, }) } @@ -88,7 +88,7 @@ func (c *RustClient) StartSyncing(t *testing.T) (stopSyncing func()) { for !isSyncing { select { case <-time.After(5 * time.Second): - t.Fatalf("[%s](rust) timed out after 5s StartSyncing", c.userID) + fatalf(t, "[%s](rust) timed out after 5s StartSyncing", c.userID) case state := <-ch: fmt.Println(state) switch state.(type) { @@ -161,7 +161,7 @@ func (c *RustClient) SendMessage(t *testing.T, roomID, text string) (eventID str r.Send(matrix_sdk_ffi.MessageEventContentFromHtml(text, text)) select { case <-time.After(5 * time.Second): - t.Fatalf("SendMessage: timed out after 5s") + fatalf(t, "SendMessage: timed out after 5s") case <-ch: return } @@ -331,11 +331,11 @@ func (w *timelineWaiter) Wait(t *testing.T, s time.Duration) { for { timeLeft := s - time.Since(start) if timeLeft <= 0 { - t.Fatalf("%s: Wait[%s]: timed out", w.client.userID, w.roomID) + fatalf(t, "%s: Wait[%s]: timed out", w.client.userID, w.roomID) } select { case <-time.After(timeLeft): - t.Fatalf("%s: Wait[%s]: timed out", w.client.userID, w.roomID) + fatalf(t, "%s: Wait[%s]: timed out", w.client.userID, w.roomID) case <-updates: if checkForEvent() { return diff --git a/tests/main_test.go b/tests/main_test.go index e1a9b1f..a522483 100644 --- a/tests/main_test.go +++ b/tests/main_test.go @@ -49,7 +49,9 @@ func TestMain(m *testing.M) { ssDeployment.Teardown() } ssMutex.Unlock() + api.WriteJSLogs() }() + api.SetupJSLogs("js_sdk.log") // rust sdk logs on its own complement.TestMain(m, "crypto") }