diff --git a/internal/api/js/chrome/chrome.go b/internal/api/js/chrome/chrome.go index f89fc12..df9c0fb 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,16 +72,52 @@ type Browser struct { Cancel func() } -func RunHeadless(onConsoleLog func(s string), requiresPersistence bool, listenPort int) (*Browser, error) { +// 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" - 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) { + writer := coloredLogWriter{colour: colour, logPrefix: logPrefix + "[chromedp " + prefix + "]", output: os.Stdout} return func(format string, args ...any) { - format = ansiRedForeground + time.Now().Format(time.RFC3339) + " [chromedp: " + prefix + "] " + format + ansiResetForeground + "\n" - fmt.Printf(format, args...) + fmt.Fprintf(writer, format, args...) } } opts := chromedp.DefaultExecAllocatorOptions[:] @@ -94,6 +132,23 @@ func RunHeadless(onConsoleLog func(s string), requiresPersistence bool, listenPo // 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")), @@ -101,6 +156,13 @@ func RunHeadless(onConsoleLog func(s string), requiresPersistence bool, listenPo // 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) { @@ -137,10 +199,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)