[botanist] Enable logger and color output

This enables the use of logger package from botanist, including support
for color output when auto-detected or explicitly requested.

Change-Id: I8f9a12b3f77a3cd2a009f1e35b4279ae8b220695
diff --git a/cmd/botanist/main.go b/cmd/botanist/main.go
index a2e7d43..db7853d 100644
--- a/cmd/botanist/main.go
+++ b/cmd/botanist/main.go
@@ -9,8 +9,24 @@
 	"os"
 
 	"github.com/google/subcommands"
+
+	"fuchsia.googlesource.com/tools/color"
+	"fuchsia.googlesource.com/tools/logger"
 )
 
+var (
+	colors color.EnableColor
+	level  logger.LogLevel
+)
+
+func init() {
+	colors = color.ColorAuto
+	level = logger.InfoLevel
+
+	flag.Var(&colors, "color", "use color in output, can be never, auto, always")
+	flag.Var(&level, "level", "output verbosity, can be fatal, error, warning, info, debug or trace")
+}
+
 func main() {
 	subcommands.Register(subcommands.HelpCommand(), "")
 	subcommands.Register(subcommands.CommandsCommand(), "")
@@ -20,5 +36,9 @@
 	subcommands.Register(&RunCommand{}, "")
 
 	flag.Parse()
-	os.Exit(int(subcommands.Execute(context.Background())))
+
+	log := logger.NewLogger(level, color.NewColor(colors), os.Stdout, os.Stderr)
+	ctx := logger.WithLogger(context.Background(), log)
+
+	os.Exit(int(subcommands.Execute(ctx)))
 }
diff --git a/cmd/botanist/qemu.go b/cmd/botanist/qemu.go
index 2956864..9be78db 100644
--- a/cmd/botanist/qemu.go
+++ b/cmd/botanist/qemu.go
@@ -9,12 +9,12 @@
 	"flag"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"os"
 	"os/exec"
 	"path/filepath"
 
 	"fuchsia.googlesource.com/tools/build"
+	"fuchsia.googlesource.com/tools/logger"
 	"fuchsia.googlesource.com/tools/qemu"
 	"fuchsia.googlesource.com/tools/secrets"
 	"github.com/google/subcommands"
@@ -133,7 +133,7 @@
 		Stdout: os.Stdout,
 		Stderr: os.Stderr,
 	}
-	log.Printf("QEMU invocation:\n%s", invocation)
+	logger.Debugf(ctx, "QEMU invocation:\n%s", invocation)
 	return qemu.CheckExitCode(qemuCmd.Run())
 }
 
@@ -145,7 +145,7 @@
 	secrets.StartSecretsServer(ctx, 8081)
 
 	if err := cmd.execute(ctx, f.Args()); err != nil {
-		log.Print(err)
+		logger.Errorf(ctx, "%v\n", err)
 		return subcommands.ExitFailure
 	}
 	return subcommands.ExitSuccess
diff --git a/cmd/botanist/run.go b/cmd/botanist/run.go
index ba6ffe1..a5f0cd3 100644
--- a/cmd/botanist/run.go
+++ b/cmd/botanist/run.go
@@ -8,7 +8,6 @@
 	"flag"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"net"
 	"os"
 	"os/exec"
@@ -18,6 +17,7 @@
 
 	"fuchsia.googlesource.com/tools/botanist"
 	"fuchsia.googlesource.com/tools/build"
+	"fuchsia.googlesource.com/tools/logger"
 	"fuchsia.googlesource.com/tools/netboot"
 	"fuchsia.googlesource.com/tools/pdu"
 	"fuchsia.googlesource.com/tools/retry"
@@ -94,7 +94,7 @@
 	}
 	go func() {
 		defer l.Close()
-		log.Printf("starting log listener\n")
+		logger.Debugf(ctx, "starting log listener\n")
 		for {
 			data, err := l.Listen()
 			if err != nil {
@@ -212,10 +212,10 @@
 
 	if properties.PDU != nil {
 		defer func() {
-			log.Printf("rebooting the node \"%s\"\n", properties.Nodename)
+			logger.Debugf(ctx, "rebooting the node %q\n", properties.Nodename)
 
 			if err := pdu.RebootDevice(properties.PDU); err != nil {
-				log.Fatalf("failed to reboot %s: %v", properties.Nodename, err)
+				logger.Fatalf(ctx, "failed to reboot %q: %v\n", properties.Nodename, err)
 			}
 		}()
 	}
@@ -241,7 +241,7 @@
 			// continue is very generous.
 			ctx, cancel := context.WithTimeout(ctx, 2*time.Minute)
 			defer cancel()
-			log.Printf("flashing to zedboot with fastboot")
+			logger.Debugf(ctx, "flashing to zedboot with fastboot\n")
 			if err := botanist.FastbootToZedboot(ctx, r.fastboot, zirconR.Path); err != nil {
 				errs <- err
 				return
@@ -266,7 +266,7 @@
 		return subcommands.ExitUsageError
 	}
 	if err := r.execute(ctx, args); err != nil {
-		log.Print(err)
+		logger.Errorf(ctx, "%v\n", err)
 		return subcommands.ExitFailure
 	}
 	return subcommands.ExitSuccess
diff --git a/cmd/botanist/zedboot.go b/cmd/botanist/zedboot.go
index b487b33..33f5c5f 100644
--- a/cmd/botanist/zedboot.go
+++ b/cmd/botanist/zedboot.go
@@ -12,7 +12,6 @@
 	"fmt"
 	"io"
 	"io/ioutil"
-	"log"
 	"net"
 	"os"
 	"os/exec"
@@ -25,6 +24,7 @@
 
 	"fuchsia.googlesource.com/tools/botanist"
 	"fuchsia.googlesource.com/tools/build"
+	"fuchsia.googlesource.com/tools/logger"
 	"fuchsia.googlesource.com/tools/netboot"
 	"fuchsia.googlesource.com/tools/pdu"
 	"fuchsia.googlesource.com/tools/retry"
@@ -108,15 +108,15 @@
 }
 
 // Creates and returns Summary file object for Host Cmds.
-func (cmd *ZedbootCommand) hostSummaryJSON(err error) (*bytes.Buffer, error) {
+func (cmd *ZedbootCommand) hostSummaryJSON(ctx context.Context, err error) (*bytes.Buffer, error) {
 	var cmdResult runtests.TestResult
 
 	if err != nil {
 		cmdResult = runtests.TestFailure
-		log.Printf("Command failed! %v\n", err)
+		logger.Infof(ctx, "Command failed! %v\n", err)
 	} else {
 		cmdResult = runtests.TestSuccess
-		log.Printf("Command succeeded!\n")
+		logger.Infof(ctx, "Command succeeded!\n")
 	}
 
 	// Create coarse-grained summary based on host command exit code
@@ -191,7 +191,7 @@
 	})
 
 	// Execute host command
-	log.Printf("Executing command: %v", cmd.hostCmd)
+	logger.Debugf(ctx, "executing command: %q\n", cmd.hostCmd)
 	hostCmd.Start()
 	hostCmdErr := hostCmd.Wait()
 
@@ -199,7 +199,7 @@
 	stdoutBuf.Write(stderrBuf.Bytes())
 
 	// Create summary JSON based on host command exit code
-	summaryBuffer, err := cmd.hostSummaryJSON(hostCmdErr)
+	summaryBuffer, err := cmd.hostSummaryJSON(ctx, hostCmdErr)
 	if err != nil {
 		return err
 	}
@@ -221,7 +221,7 @@
 	}
 	go func() {
 		defer l.Close()
-		log.Printf("starting log listener\n")
+		logger.Debugf(ctx, "starting log listener\n")
 		for {
 			data, err := l.Listen()
 			if err != nil {
@@ -265,7 +265,7 @@
 		return cmd.runHostCmd(ctx)
 	}
 
-	log.Printf("waiting for \"%s\"\n", cmd.summaryFilename)
+	logger.Debugf(ctx, "waiting for %q\n", cmd.summaryFilename)
 
 	// Poll for summary.json; this relies on runtest being executed using
 	// autorun and it eventually producing the summary.json file.
@@ -285,7 +285,7 @@
 		return fmt.Errorf("timed out waiting for tests to complete: %v", err)
 	}
 
-	log.Printf("reading \"%s\"\n", cmd.summaryFilename)
+	logger.Debugf(ctx, "reading %q\n", cmd.summaryFilename)
 
 	if _, err := writer.WriteTo(&buffer); err != nil {
 		return fmt.Errorf("failed to receive summary file: %v\n", err)
@@ -309,7 +309,7 @@
 		return err
 	}
 
-	log.Printf("copying test output\n")
+	logger.Debugf(ctx, "copying test output\n")
 
 	// Tar in a subroutine while busy-printing so that we do not hit an i/o timeout when
 	// dealing with large files.
@@ -343,7 +343,7 @@
 		c <- nil
 	}()
 
-	log.Printf("tarring test output...")
+	logger.Debugf(ctx, "tarring test output...\n")
 	ticker := time.NewTicker(5 * time.Second)
 	for {
 		select {
@@ -351,7 +351,7 @@
 			ticker.Stop()
 			return err
 		case <-ticker.C:
-			log.Printf("tarring test output...")
+			logger.Debugf(ctx, "tarring test output...\n")
 		}
 	}
 }
@@ -364,10 +364,10 @@
 
 	if properties.PDU != nil {
 		defer func() {
-			log.Printf("rebooting the node \"%s\"\n", properties.Nodename)
+			logger.Debugf(ctx, "rebooting the node %q\n", properties.Nodename)
 
 			if err := pdu.RebootDevice(properties.PDU); err != nil {
-				log.Fatalf("failed to reboot the device: %v", err)
+				logger.Fatalf(ctx, "failed to reboot the device: %v\n", err)
 			}
 		}()
 	}
@@ -397,7 +397,7 @@
 			// continue is very generous.
 			ctx, cancel := context.WithTimeout(ctx, 2*time.Minute)
 			defer cancel()
-			log.Printf("flashing to zedboot with fastboot")
+			logger.Debugf(ctx, "flashing to zedboot with fastboot\n")
 			if err := botanist.FastbootToZedboot(ctx, cmd.fastboot, zirconR.Path); err != nil {
 				errs <- err
 				return
@@ -418,21 +418,21 @@
 
 func (cmd *ZedbootCommand) Execute(ctx context.Context, f *flag.FlagSet, _ ...interface{}) subcommands.ExitStatus {
 	propertiesFlag := f.Lookup("properties")
-	log.Printf("properties flag: %v", propertiesFlag.Value)
+	logger.Debugf(ctx, "properties flag: %v\n", propertiesFlag.Value)
 
 	// Aggregate command-line arguments.
 	cmdlineArgs := f.Args()
 	if cmd.cmdlineFile != "" {
 		args, err := ioutil.ReadFile(cmd.cmdlineFile)
 		if err != nil {
-			log.Printf("failed to read command-line args file \"%v\": %v", cmd.cmdlineFile, err)
+			logger.Errorf(ctx, "failed to read command-line args file %q: %v\n", cmd.cmdlineFile, err)
 			return subcommands.ExitFailure
 		}
 		cmdlineArgs = append(cmdlineArgs, strings.Split(string(args), "\n")...)
 	}
 
 	if err := cmd.execute(ctx, cmdlineArgs); err != nil {
-		log.Print(err)
+		logger.Errorf(ctx, "%v\n", err)
 		return subcommands.ExitFailure
 	}
 
diff --git a/cmd/symbolize/main.go b/cmd/symbolize/main.go
index 7fec4d0..b2f845d 100644
--- a/cmd/symbolize/main.go
+++ b/cmd/symbolize/main.go
@@ -8,9 +8,7 @@
 	"context"
 	"encoding/json"
 	"flag"
-	"fmt"
 	"io"
-	"log"
 	"os"
 
 	"fuchsia.googlesource.com/tools/color"
@@ -19,32 +17,27 @@
 )
 
 var (
-	llvmSymboPath string
-	idsPath       string
-	colorValue    string
+	colors        color.EnableColor
 	jsonOutput    string
+	idsPath       string
 	// TODO(jakehehrlich): Make idsRel always true and remove this flag.
-	idsRel bool
+	idsRel        bool
+	level         logger.LogLevel
+	llvmSymboPath string
 )
 
 func init() {
+	colors = color.ColorAuto
+	level = logger.InfoLevel
+
 	flag.StringVar(&llvmSymboPath, "llvm-symbolizer", "llvm-symbolizer", "path to llvm-symbolizer")
 	flag.StringVar(&idsPath, "ids", "", "path to ids.txt")
-	flag.StringVar(&colorValue, "color", "auto", "can be `always`, `auto`, or `never`.")
+	flag.Var(&colors, "color", "use color in output, can be never, auto, always")
+	flag.Var(&level, "level", "output verbosity, can be fatal, error, warning, info, debug or trace")
 	flag.StringVar(&jsonOutput, "json-output", "", "outputs trigger information to the specified file")
 	flag.BoolVar(&idsRel, "ids-rel", false, "tells the symbolizer to always use ids.txt relative paths")
 }
 
-func getColor() (color.Color, error) {
-	ec := color.EnableColor(colorValue)
-	switch ec {
-	case color.ColorAlways, color.ColorNever, color.ColorAuto:
-		return color.NewColor(ec), nil
-	default:
-		return nil, fmt.Errorf("invalid color option `%s`, possible values are `always`, `auto`, and `never`", colorValue)
-	}
-}
-
 type dumpEntry struct {
 	Modules  []symbolize.Module  `json:"modules"`
 	Segments []symbolize.Segment `json:"segments"`
@@ -79,25 +72,22 @@
 func main() {
 	// Parse flags and setup helpers
 	flag.Parse()
-	painter, err := getColor()
-	if err != nil {
-		log.Fatal(err)
-	}
 	var jsonTriggerHandler *dumpHandler
 	if jsonOutput != "" {
 		jsonTriggerHandler = &dumpHandler{}
 	}
 
 	// Setup logger and context
-	symbolizeLogger := logger.NewLogger(logger.WarningLevel, painter, os.Stderr, os.Stderr)
-	ctx := logger.WithLogger(context.Background(), symbolizeLogger)
+	painter := color.NewColor(colors)
+	log := logger.NewLogger(level, painter, os.Stdout, os.Stderr)
+	ctx := logger.WithLogger(context.Background(), log)
 
 	// Construct the nodes of the pipeline
 	symbolizer := symbolize.NewLLVMSymbolizer(llvmSymboPath)
 	repo := symbolize.NewRepo()
-	err = repo.AddSource(symbolize.NewIDsSource(idsPath, idsRel))
+	err := repo.AddSource(symbolize.NewIDsSource(idsPath, idsRel))
 	if err != nil {
-		symbolizeLogger.Fatalf("%v", err)
+		log.Fatalf("%v\n", err)
 	}
 	demuxer := symbolize.NewDemuxer(repo, symbolizer)
 	tap := symbolize.NewTriggerTap()
@@ -109,7 +99,7 @@
 	// Build the pipeline to start presenting.
 	err = symbolizer.Start(ctx)
 	if err != nil {
-		symbolizeLogger.Fatalf("%v", err)
+		log.Fatalf("%v\n", err)
 	}
 	inputLines := symbolize.StartParsing(ctx, os.Stdin)
 	outputLines := demuxer.Start(ctx, inputLines)
@@ -124,10 +114,10 @@
 	if jsonTriggerHandler != nil {
 		file, err := os.Create(jsonOutput)
 		if err != nil {
-			log.Fatal(err)
+			log.Fatalf("%v\n", err)
 		}
 		if err := jsonTriggerHandler.Write(file); err != nil {
-			log.Fatal(err)
+			log.Fatalf("%v\n", err)
 		}
 	}
 }
diff --git a/color/color.go b/color/color.go
index a880820..168bc7e 100644
--- a/color/color.go
+++ b/color/color.go
@@ -98,12 +98,12 @@
 	return false
 }
 
-type EnableColor string
+type EnableColor int
 
 const (
-	ColorAlways EnableColor = "always"
-	ColorNever  EnableColor = "never"
-	ColorAuto   EnableColor = "auto"
+	ColorNever EnableColor = iota
+	ColorAuto
+	ColorAlways
 )
 
 func isColorAvailable() bool {
@@ -126,3 +126,29 @@
 		return monochrome{}
 	}
 }
+
+func (ec *EnableColor) String() string {
+	switch *ec {
+	case ColorNever:
+		return "never"
+	case ColorAuto:
+		return "auto"
+	case ColorAlways:
+		return "always"
+	}
+	return ""
+}
+
+func (ec *EnableColor) Set(s string) error {
+	switch s {
+	case "never":
+		*ec = ColorNever
+	case "auto":
+		*ec = ColorAuto
+	case "always":
+		*ec = ColorAlways
+	default:
+		return fmt.Errorf("%s is not a valid color value", s)
+	}
+	return nil
+}
diff --git a/logger/logger.go b/logger/logger.go
index 70c637e..89803ae 100644
--- a/logger/logger.go
+++ b/logger/logger.go
@@ -39,6 +39,46 @@
 	TraceLevel
 )
 
+func (l *LogLevel) String() string {
+	switch *l {
+	case NoLogLevel:
+		return "no"
+	case FatalLevel:
+		return "fatal"
+	case ErrorLevel:
+		return "error"
+	case WarningLevel:
+		return "warning"
+	case InfoLevel:
+		return "info"
+	case DebugLevel:
+		return "debug"
+	case TraceLevel:
+		return "trace"
+	}
+	return ""
+}
+
+func (l *LogLevel) Set(s string) error {
+	switch s {
+	case "fatal":
+		*l = FatalLevel
+	case "error":
+		*l = ErrorLevel
+	case "warning":
+		*l = WarningLevel
+	case "info":
+		*l = InfoLevel
+	case "debug":
+		*l = DebugLevel
+	case "trace":
+		*l = TraceLevel
+	default:
+		return fmt.Errorf("%s is not a valid level", s)
+	}
+	return nil
+}
+
 func NewLogger(loggerLevel LogLevel, color color.Color, outWriter, errWriter io.Writer) *Logger {
 	if outWriter == nil {
 		outWriter = os.Stdout