Log to file and upload as artifacts; better colours on failures

.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

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`

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...)
+}

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,15 +78,15 @@ 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)
 					// for now the format is always 'room_id||{event}'
 					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...)

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

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")
 
 }