more log line grouping in GitHub actions

Author: joonas-fi

cmd/bob/build.go

@@ -3,6 +3,7 @@ package main
 import (
 	"errors"
 	"fmt"
+	"io"
 	"os"
 	"os/exec"
 	"path/filepath"
@@ -35,7 +36,27 @@ func runBuilder(builder BuilderSpec, buildCtx *BuildContext, opDesc string, cmdT
 		return errWd
 	}
 
-	printHeading(fmt.Sprintf("%s/%s (%s)", builder.Name, opDesc, builderCommandToHumanReadable(cmdToRun)))
+	builderNameOpDesc := fmt.Sprintf("%s/%s", builder.Name, opDesc)
+
+	switch must(parseBuilderUsesType(builder.Uses)) {
+	case builderUsesTypeImage:
+		// the "$ docker run ..." later would do an implicit pull, but let's do an explicit pull
+		// here in order to nicely put the download progress output in its own log line group
+		if err := withLogLineGroup(fmt.Sprintf("%s > pull", builderNameOpDesc), func() error {
+			return dockerPullIfRequired(builderImageName(buildCtx.Bobfile, builder))
+		}); err != nil {
+			return err
+		}
+	case builderUsesTypeDockerfile:
+		// no-op (doesn't need a pull)
+	default:
+		panic("unknown builderType")
+	}
+
+	// empty work just to emit a "starting" log group. this log group is important because if the
+	// command-to-run itself doesn't create log groups (to which we could insert script name), then
+	// script name won't be visible at all in none of the group names
+	_ = withLogLineGroup(fmt.Sprintf("%s > starting %s", builderNameOpDesc, builderCommandToHumanReadable(cmdToRun)), func() error { return nil })
 
 	buildArgs := []string{
 		"docker",
@@ -78,7 +99,23 @@ func runBuilder(builder BuilderSpec, buildCtx *BuildContext, opDesc string, cmdT
 	}
 
 	//nolint:gosec // ok
-	buildCmd := passthroughStdoutAndStderr(exec.Command(buildArgs[0], buildArgs[1:]...))
+	buildCmd := exec.Command(buildArgs[0], buildArgs[1:]...)
+	buildCmd.Stdout = newLineSplitterTee(io.Discard, func(line string) {
+		lineMaybeModified := func() string {
+			// for each log line group, add "breadcrumb prefix" of builder / operation description.
+			// example group name: "staticAnalysis" => "default/build > staticAnalysis"
+			if strings.HasPrefix(line, "::group::") {
+				originalGroupName := line[len("::group::"):]
+
+				return fmt.Sprintf("::group::%s > %s", builderNameOpDesc, originalGroupName)
+			} else {
+				return line // as-is
+			}
+		}()
+
+		_, _ = os.Stdout.Write([]byte(lineMaybeModified + "\n")) // need to add newline back
+	})
+	buildCmd.Stderr = os.Stderr
 
 	if err := buildCmd.Run(); err != nil {
 		return err
@@ -435,7 +472,7 @@ func buildEntry() *cobra.Command {
 		Args:  cobra.NoArgs,
 		Run: func(cmd *cobra.Command, args []string) {
 			osutil.ExitIfError(func() error {
-				if os.Getenv("GITHUB_ACTIONS") != "true" {
+				if !runningInGitHubActions() {
 					return errors.New("expecting GITHUB_ACTIONS=true")
 				}
 

cmd/bob/docker.go

@@ -159,7 +159,7 @@ func dockerRelayEnvVars(
 
 	// "Always set to true when GitHub Actions is running the workflow. You can use this variable to
 	// differentiate when tests are being run locally or by GitHub Actions."
-	if os.Getenv("GITHUB_ACTIONS") == "true" { // relay as-is
+	if runningInGitHubActions() { // relay as-is
 		env("GITHUB_ACTIONS", "true")
 	}
 
@@ -212,6 +212,20 @@ func loginToDockerRegistry(dockerImage DockerImageSpec, cache *dockerRegistryLog
 	return nil
 }
 
+func dockerPullIfRequired(imageRef string) error {
+	// there's no flag to "$ docker pull" that could allow us to say "please don't check the registry
+	// for newest version of that tag if we already have any version", so let's first query Docker
+	// if we already have the image, in order to not query the registry many times. use cases:
+	// - repeated "$ bob build" invocations
+	// - same builder used multiple times in the project
+	alreadyHave := exec.Command("docker", "image", "inspect", imageRef).Run()
+	if alreadyHave == nil { // this has error if we don't have the image yet
+		return nil
+	}
+
+	return passthroughStdoutAndStderr(exec.Command("docker", "pull", imageRef)).Run()
+}
+
 type dockerRegistryLoginCacheKey string
 
 func newDockerRegistryLoginCacheKey(registry string, creds DockerCredentials) dockerRegistryLoginCacheKey {

cmd/bob/utils.go

@@ -1,8 +1,12 @@
 package main
 
 import (
+	"fmt"
+	"io"
 	"os"
 	"os/exec"
+	"strings"
+	"sync"
 )
 
 func passthroughStdoutAndStderr(cmd *exec.Cmd) *exec.Cmd {
@@ -24,3 +28,66 @@ func allDevShellCommands(devShellCommands []DevShellCommand) []string {
 
 	return commands
 }
+
+func runningInGitHubActions() bool {
+	return os.Getenv("GITHUB_ACTIONS") == "true"
+}
+
+func must(input builderUsesType, _ string, err error) builderUsesType {
+	if err != nil {
+		panic(err)
+	}
+	return input
+}
+
+func withLogLineGroup(group string, work func() error) error {
+	if !runningInGitHubActions() {
+		printHeading(group)
+		return work()
+	}
+
+	fmt.Println("::group::" + group)
+
+	err := work()
+
+	fmt.Println("::endgroup::")
+
+	return err
+}
+
+// FIXME: lineSplitterTee should maybe go to gokit? other use is in Varasto
+
+type lineSplitterTee struct {
+	buf           []byte // buffer before receiving \n
+	lineCompleted func(string)
+	mu            sync.Mutex
+}
+
+// returns io.Writer that tees full lines to lineCompleted callback
+func newLineSplitterTee(sink io.Writer, lineCompleted func(string)) io.Writer {
+	return io.MultiWriter(sink, &lineSplitterTee{
+		buf:           []byte{},
+		lineCompleted: lineCompleted,
+	})
+}
+
+func (l *lineSplitterTee) Write(data []byte) (int, error) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	l.buf = append(l.buf, data...)
+
+	// as long as we have lines, chop the buffer down
+	for {
+		idx := strings.IndexByte(string(l.buf), '\n')
+		if idx == -1 {
+			break
+		}
+
+		l.lineCompleted(string(l.buf[0:idx]))
+
+		l.buf = l.buf[idx+1:]
+	}
+
+	return len(data), nil
+}