From 760f10fd3c852fdb2da02321f7513bd0a0195047 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 18 Mar 2026 07:41:49 +0000 Subject: [PATCH 1/4] Pass an identifier for the client into RunHeadless so that we can distinguish output from differrent instances --- internal/api/js/chrome/chrome.go | 10 +++++----- internal/api/js/js.go | 2 +- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/internal/api/js/chrome/chrome.go b/internal/api/js/chrome/chrome.go index f89fc12..0f5dd6b 100644 --- a/internal/api/js/chrome/chrome.go +++ b/internal/api/js/chrome/chrome.go @@ -70,7 +70,7 @@ type Browser struct { Cancel func() } -func RunHeadless(onConsoleLog func(s string), requiresPersistence bool, listenPort int) (*Browser, error) { +func RunHeadless(logPrefix string, onConsoleLog func(s string), requiresPersistence bool, listenPort int) (*Browser, error) { ansiRedForeground := "\x1b[31m" ansiYellowForeground := "\x1b[33m" ansiResetForeground := "\x1b[39m" @@ -78,7 +78,7 @@ func RunHeadless(onConsoleLog func(s string), requiresPersistence bool, listenPo // colorifyError returns a log format function which prints its input with a given prefix and colour. colorifyError := func(colour string, prefix string) func(format string, args ...any) { return func(format string, args ...any) { - format = ansiRedForeground + time.Now().Format(time.RFC3339) + " [chromedp: " + prefix + "] " + format + ansiResetForeground + "\n" + format = ansiRedForeground + time.Now().Format(time.RFC3339) + " " + logPrefix + "[chromedp " + prefix + "] " + format + ansiResetForeground + "\n" fmt.Printf(format, args...) } } @@ -137,10 +137,10 @@ func RunHeadless(onConsoleLog func(s string), requiresPersistence bool, listenPo panic(err) } baseJSURL = "http://" + ln.Addr().String() - fmt.Println("JS SDK listening on", baseJSURL) + fmt.Println(logPrefix, "JS SDK wrapper listening on", baseJSURL) wg.Done() - srv.Serve(ln) - fmt.Println("JS SDK closing webserver") + err = srv.Serve(ln) + fmt.Printf("%s Closing webserver for JS SDK wrapper at %s: %v\n", logPrefix, baseJSURL, err) } go startServer() wg.Wait() diff --git a/internal/api/js/js.go b/internal/api/js/js.go index 04d3b77..f5c342b 100644 --- a/internal/api/js/js.go +++ b/internal/api/js/js.go @@ -69,7 +69,7 @@ func NewJSClient(t ct.TestLike, opts api.ClientCreationOpts) (api.Client, error) verificationChannelMu: &sync.Mutex{}, } portKey := opts.UserID + opts.DeviceID - browser, err := chrome.RunHeadless(func(s string) { + browser, err := chrome.RunHeadless(fmt.Sprintf("[JSClient %s,%s]", opts.UserID, opts.DeviceID), func(s string) { writeToLog("[%s,%s] console.log %s\n", opts.UserID, opts.DeviceID, s) msg := unpackControlMessage(t, s) From bd38a609d6e515c27302dcc0b92d5b31c0b864c6 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 18 Mar 2026 07:43:19 +0000 Subject: [PATCH 2/4] Factor log decorating logic out into a Writer ... to make it usable in more places, and for encapsulation --- internal/api/js/chrome/chrome.go | 42 ++++++++++++++++++++++++++++++-- 1 file changed, 40 insertions(+), 2 deletions(-) diff --git a/internal/api/js/chrome/chrome.go b/internal/api/js/chrome/chrome.go index 0f5dd6b..ab8a6cb 100644 --- a/internal/api/js/chrome/chrome.go +++ b/internal/api/js/chrome/chrome.go @@ -12,9 +12,11 @@ import ( "net" "net/http" "os" + "os/exec" "path/filepath" "strconv" "sync" + "syscall" "time" "github.com/chromedp/cdproto/runtime" @@ -70,6 +72,42 @@ type Browser struct { Cancel func() } +// colouredLogWriter is an implementation of `io.Writer` which wraps an `os.File`, adding the date and logPrefix to each line, +// and decorating the text in a specific colour. +type coloredLogWriter struct { + colour string + logPrefix string + output *os.File +} + +func (w coloredLogWriter) Write(p []byte) (n int, err error) { + _, err = w.output.WriteString(w.colour) + if err != nil { + return + } + + last := byte('\n') + for _, c := range p { + // If this is the first byte after a newline, add the date and prefix + if last == '\n' { + _, err = w.output.WriteString(time.Now().Format(time.RFC3339) + " " + w.logPrefix + " ") + if err != nil { + return + } + } + _, err = w.output.Write([]byte{c}) + if err != nil { + return + } + n += 1 + last = c + } + + ansiResetForeground := "\x1b[39m" + _, err = w.output.WriteString(ansiResetForeground) + return +} + func RunHeadless(logPrefix string, onConsoleLog func(s string), requiresPersistence bool, listenPort int) (*Browser, error) { ansiRedForeground := "\x1b[31m" ansiYellowForeground := "\x1b[33m" @@ -77,9 +115,9 @@ func RunHeadless(logPrefix string, onConsoleLog func(s string), requiresPersiste // colorifyError returns a log format function which prints its input with a given prefix and colour. colorifyError := func(colour string, prefix string) func(format string, args ...any) { + writer := coloredLogWriter{colour: colour, logPrefix: logPrefix + "[chromedp " + prefix + "]", output: os.Stdout} return func(format string, args ...any) { - format = ansiRedForeground + time.Now().Format(time.RFC3339) + " " + logPrefix + "[chromedp " + prefix + "] " + format + ansiResetForeground + "\n" - fmt.Printf(format, args...) + fmt.Fprintf(writer, format, args...) } } opts := chromedp.DefaultExecAllocatorOptions[:] From 028706f84208719a0d804ab88d590a49f17bbada Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 18 Mar 2026 07:44:31 +0000 Subject: [PATCH 3/4] Log the command line and stdout/err from Chrome ... in the hope that this sheds osme light on why it's not listening on the websocket --- internal/api/js/chrome/chrome.go | 19 ++++++++++++++++++- 1 file changed, 18 insertions(+), 1 deletion(-) diff --git a/internal/api/js/chrome/chrome.go b/internal/api/js/chrome/chrome.go index ab8a6cb..4719ce3 100644 --- a/internal/api/js/chrome/chrome.go +++ b/internal/api/js/chrome/chrome.go @@ -111,7 +111,7 @@ func (w coloredLogWriter) Write(p []byte) (n int, err error) { func RunHeadless(logPrefix string, onConsoleLog func(s string), requiresPersistence bool, listenPort int) (*Browser, error) { ansiRedForeground := "\x1b[31m" ansiYellowForeground := "\x1b[33m" - ansiResetForeground := "\x1b[39m" + ansiBlueForeground := "\x1b[34m" // colorifyError returns a log format function which prints its input with a given prefix and colour. colorifyError := func(colour string, prefix string) func(format string, args ...any) { @@ -132,6 +132,23 @@ func RunHeadless(logPrefix string, onConsoleLog func(s string), requiresPersiste // increase the WS timeout from 20s (default) to 30s as we see timeouts with 20s in CI opts = append(opts, chromedp.WSURLReadTimeout(30*time.Second)) + // Capture stdout/stderr from Chrome, and log it. + opts = append(opts, chromedp.CombinedOutput(coloredLogWriter{colour: ansiBlueForeground, logPrefix: logPrefix + " chrome:", output: os.Stdout})) + + // Hook into chromedp to log the command that is about to be executed. The easiest way to do that seems to be to + // set a ModifyCmdFunc. + opts = append(opts, chromedp.ModifyCmdFunc(func(cmd *exec.Cmd) { + writer := coloredLogWriter{colour: ansiBlueForeground, logPrefix: logPrefix, output: os.Stdout} + fmt.Fprintf(writer, "Executing: %v\n", cmd.Args) + + // Replicate the behaviour of the default ModifyCmdFunc: tell the kernel to send the child a SIGKILL when the + // parent thread dies. + if cmd.SysProcAttr == nil { + cmd.SysProcAttr = new(syscall.SysProcAttr) + } + cmd.SysProcAttr.Pdeathsig = syscall.SIGKILL + })) + allocCtx, allocCancel := chromedp.NewExecAllocator(context.Background(), opts...) ctx, cancel := chromedp.NewContext(allocCtx, chromedp.WithBrowserOption( chromedp.WithBrowserLogf(colorifyError(ansiYellowForeground, "LOG")), From 27f46800e49b68ffb4b2488e0c2f48ec16bdf9aa Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 18 Mar 2026 07:45:39 +0000 Subject: [PATCH 4/4] Try connecting to chrome earlier ... so that it's less confusing when it doesn't work --- internal/api/js/chrome/chrome.go | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/internal/api/js/chrome/chrome.go b/internal/api/js/chrome/chrome.go index 4719ce3..df9c0fb 100644 --- a/internal/api/js/chrome/chrome.go +++ b/internal/api/js/chrome/chrome.go @@ -156,6 +156,13 @@ func RunHeadless(logPrefix string, onConsoleLog func(s string), requiresPersiste // chromedp.WithBrowserDebugf(log.Printf), )) + // Make sure we can talk to Chrome before we start messing about with js-sdk + fmt.Println("Starting chrome via chromedp") + err := chromedp.Run(ctx, chromedp.Evaluate(`(() => 1)()`, nil)) + if err != nil { + return nil, fmt.Errorf("failed to run test evaluation via chromedp: %w", err) + } + // Listen for console logs for debugging AND to communicate live updates chromedp.ListenTarget(ctx, func(ev interface{}) { switch ev := ev.(type) {