Make output more compact and easier to read (#295)

Build output now includes a target and command heading. Info-level log
lines no longer have the unhelpful "INFO" prefix. All non-error build
output now goes to stdout so someone who wants a more quiet experience
for a successful build can redirect to `/dev/null`.

Individual lines of command and log output now also include the target
they are running for and the time the line was outputted. This serves to
both visually group outputs by command as well as provide fine-grained
timing information.

Also propagate `NO_COLOR` to build environment.

[Fixes ch4043]
[Fixes ch4040]

Author: zombiezen

CHANGELOG.md

@@ -22,11 +22,17 @@ The format is based on [Keep a Changelog][], and this project adheres to
    error if the targets have a dependency cycle.
 -  yb attempts to detect some common Docker configuration issues and inform the
    user about them.
+-  yb now obeys the [`NO_COLOR` environment variable][] and propagates it to the
+   build environment.
+
+[`NO_COLOR` environment variable]: https://no-color.org/
 
 ### Changed
 
 -  Commands run as part of `build`, `exec`, or `run` now run without Docker by
    default. You can get the old behavior by running with `--mode=container`.
+-  Tool output has been changed to be more compact, to be easier to trace
+   command output, and to include more timing information.
 -  `yb platform` is now an alias for `yb version`.
 
 ### Fixed

cmd/yb/build.go

@@ -3,7 +3,7 @@ package main
 import (
 	"context"
 	"fmt"
-	"io/ioutil"
+	"io"
 	"os"
 	"strings"
 	"time"
@@ -98,6 +98,7 @@ func (b *buildCmd) run(ctx context.Context) error {
 	startTime := time.Now()
 	ctx, span := ybtrace.Start(ctx, "Build", trace.WithNewRoot())
 	defer span.End()
+	ctx = withStdoutLogs(ctx)
 
 	log.Infof(ctx, "Build started at %s", startTime.Format(longTimeFormat))
 
@@ -117,10 +118,10 @@ func (b *buildCmd) run(ctx context.Context) error {
 	showDockerWarningsIfNeeded(ctx, b.mode, buildTargets)
 
 	// Do the build!
-	startSection("BUILD")
 	log.Debugf(ctx, "Building package %s in %s...", targetPackage.Name, targetPackage.Path)
 
 	buildError := doTargetList(ctx, targetPackage, buildTargets, &doOptions{
+		output:        os.Stdout,
 		executionMode: b.mode,
 		dockerClient:  dockerClient,
 		dataDirs:      dataDirs,
@@ -132,27 +133,27 @@ func (b *buildCmd) run(ctx context.Context) error {
 	})
 	if buildError != nil {
 		span.SetStatus(codes.Unknown, buildError.Error())
+		log.Errorf(ctx, "%v", buildError)
 	}
 	span.End()
 	endTime := time.Now()
 	buildTime := endTime.Sub(startTime)
 
-	log.Infof(ctx, "")
-	log.Infof(ctx, "Build finished at %s, taking %s", endTime.Format(longTimeFormat), buildTime)
-	log.Infof(ctx, "")
-
-	log.Infof(ctx, "%s", buildTraces.dump())
+	fmt.Printf("\nBuild finished at %s, taking %v\n\n", endTime.Format(longTimeFormat), buildTime.Truncate(time.Millisecond))
+	fmt.Println(buildTraces.dump())
 
+	style := termStylesFromEnv()
 	if buildError != nil {
-		subSection("BUILD FAILED")
-		return buildError
+		fmt.Printf("%sBUILD FAILED%s ❌\n", style.buildResult(false), style.reset())
+		return alreadyLoggedError{buildError}
 	}
 
-	subSection("BUILD SUCCEEDED")
+	fmt.Printf("%sBUILD PASSED%s ️✔️\n", style.buildResult(true), style.reset())
 	return nil
 }
 
 type doOptions struct {
+	output          io.Writer
 	dataDirs        *ybdata.Dirs
 	downloader      *ybdata.Downloader
 	executionMode   executionMode
@@ -198,6 +199,11 @@ func doTargetList(ctx context.Context, pkg *yb.Package, targets []*yb.Target, op
 }
 
 func doTarget(ctx context.Context, pkg *yb.Package, target *yb.Target, opts *doOptions) error {
+	style := termStylesFromEnv()
+	fmt.Printf("\n🎯 %sTarget: %s%s\n", style.target(), target.Name, style.reset())
+
+	ctx = withLogPrefix(ctx, target.Name)
+
 	bio, err := newBiome(ctx, target, newBiomeOptions{
 		packageDir:      pkg.Path,
 		dataDirs:        opts.dataDirs,
@@ -216,15 +222,17 @@ func doTarget(ctx context.Context, pkg *yb.Package, target *yb.Target, opts *doO
 			log.Warnf(ctx, "Clean up environment: %v", err)
 		}
 	}()
+	output := newLinePrefixWriter(opts.output, target.Name)
 	sys := build.Sys{
 		Biome:           bio,
 		Downloader:      opts.downloader,
 		DockerClient:    opts.dockerClient,
 		DockerNetworkID: opts.dockerNetworkID,
-		Stdout:          os.Stdout,
-		Stderr:          os.Stderr,
+
+		Stdout: output,
+		Stderr: output,
 	}
-	execBiome, err := build.Setup(ctx, sys, target)
+	execBiome, err := build.Setup(withLogPrefix(ctx, setupLogPrefix), sys, target)
 	if err != nil {
 		return err
 	}
@@ -241,34 +249,15 @@ func doTarget(ctx context.Context, pkg *yb.Package, target *yb.Target, opts *doO
 		return nil
 	}
 
-	subSection(fmt.Sprintf("Build target: %s", target.Name))
-	log.Infof(ctx, "Executing build steps...")
-	return build.Execute(ctx, sys, target)
+	return build.Execute(withStdoutLogs(ctx), sys, announceCommand, target)
 }
 
-// Because, why not?
-// Based on https://github.com/sindresorhus/is-docker/blob/master/index.js and https://github.com/moby/moby/issues/18355
-// Discussion is not settled yet: https://stackoverflow.com/questions/23513045/how-to-check-if-a-process-is-running-inside-docker-container#25518538
-func insideTheMatrix() bool {
-	hasDockerEnv := pathExists("/.dockerenv")
-	hasDockerCGroup := false
-	dockerCGroupPath := "/proc/self/cgroup"
-	if pathExists(dockerCGroupPath) {
-		contents, _ := ioutil.ReadFile(dockerCGroupPath)
-		hasDockerCGroup = strings.Count(string(contents), "docker") > 0
-	}
-	return hasDockerEnv || hasDockerCGroup
+func announceCommand(cmdString string) {
+	style := termStylesFromEnv()
+	fmt.Printf("%s> %s%s\n", style.command(), cmdString, style.reset())
 }
 
 func pathExists(path string) bool {
 	_, err := os.Lstat(path)
 	return !os.IsNotExist(err)
 }
-
-func startSection(name string) {
-	fmt.Printf(" === %s ===\n", name)
-}
-
-func subSection(name string) {
-	fmt.Printf(" -- %s -- \n", name)
-}

cmd/yb/exec.go

@@ -99,7 +99,7 @@ func (b *execCmd) run(ctx context.Context) error {
 		Stdout:          os.Stdout,
 		Stderr:          os.Stderr,
 	}
-	execBiome, err := build.Setup(ctx, sys, execTarget)
+	execBiome, err := build.Setup(withLogPrefix(ctx, execTarget.Name+setupLogPrefix), sys, execTarget)
 	if err != nil {
 		return err
 	}
@@ -109,5 +109,5 @@ func (b *execCmd) run(ctx context.Context) error {
 			log.Errorf(ctx, "Clean up environment %s: %v", b.execEnvName, err)
 		}
 	}()
-	return build.Execute(ctx, sys, execTarget)
+	return build.Execute(ctx, sys, announceCommand, execTarget)
 }

cmd/yb/main.go

@@ -2,6 +2,7 @@ package main
 
 import (
 	"context"
+	"errors"
 	"fmt"
 	"os"
 	"path/filepath"
@@ -87,12 +88,28 @@ func main() {
 	err = rootCmd.ExecuteContext(ctx)
 	cancel()
 	if err != nil {
-		initLog(cfg, false)
-		log.Errorf(ctx, "%v", err)
+		if !errors.As(err, new(alreadyLoggedError)) {
+			initLog(cfg, false)
+			log.Errorf(ctx, "%v", err)
+		}
 		os.Exit(1)
 	}
 }
 
+// alreadyLoggedError wraps another error to signal that it has already been
+// shown to the user. If returned from a subcommand, then main() will not log it.
+type alreadyLoggedError struct {
+	err error
+}
+
+func (e alreadyLoggedError) Error() string {
+	return e.err.Error()
+}
+
+func (e alreadyLoggedError) Unwrap() error {
+	return e.err
+}
+
 func displayOldDirectoryWarning(ctx context.Context) {
 	home := os.Getenv("HOME")
 	if home == "" {