*: improve logging messages

This slightly improves some of the logging messages and hides the
Terraform output by default (it can still be enabled by setting the log
level to debug). Installing a cluster with libvirt looks like the
following:

    INFO Fetching OS image...
    INFO Using Terraform to create cluster...

Author: crawford

cmd/openshift-install/main.go

@@ -4,7 +4,7 @@ import (
 	"fmt"
 	"os"
 
-	log "github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus"
 	"gopkg.in/alecthomas/kingpin.v2"
 
 	"github.com/openshift/installer/pkg/asset"
@@ -23,19 +23,24 @@ var (
 	destroyCommand = kingpin.Command("destroy-cluster", "Destroy an OpenShift cluster")
 
 	dirFlag  = kingpin.Flag("dir", "assets directory").Default(".").String()
-	logLevel = kingpin.Flag("log-level", "log level (e.g. \"debug\")").Default("warn").Enum("debug", "info", "warn", "error", "fatal", "panic")
+	logLevel = kingpin.Flag("log-level", "log level (e.g. \"debug\")").Default("info").Enum("debug", "info", "warn", "error")
 
 	version = "was not built correctly" // set in hack/build.sh
 )
 
 func main() {
 	command := kingpin.Parse()
-	l, err := log.ParseLevel(*logLevel)
-	if err != nil {
+
+	logrus.SetFormatter(&logrus.TextFormatter{
+		DisableTimestamp:       true,
+		DisableLevelTruncation: true,
+	})
+	if level, err := logrus.ParseLevel(*logLevel); err == nil {
+		logrus.SetLevel(level)
+	} else {
 		// By definition we should never enter this condition since kingpin should be guarding against incorrect values.
-		log.Fatalf("invalid log-level: %v", err)
+		logrus.Panicf("Invalid log-level: %v", err)
 	}
-	log.SetLevel(l)
 
 	if command == versionCommand.FullCommand() {
 		fmt.Printf("%s %s\n", os.Args[0], version)
@@ -77,26 +82,20 @@ func main() {
 		for _, asset := range targetAssets {
 			st, err := assetStore.Fetch(asset)
 			if err != nil {
-				log.Fatalf("failed to generate asset: %v", err)
-				os.Exit(1)
+				logrus.Fatalf("Failed to generate asset: %v", err)
 			}
 
 			if err := st.PersistToFile(*dirFlag); err != nil {
-				log.Fatalf("failed to write target to disk: %v", err)
-				os.Exit(1)
+				logrus.Fatalf("Failed to write asset (%s) to disk: %v", asset.Name(), err)
 			}
 		}
 	case destroyCommand.FullCommand():
-		destroyer, err := destroy.New(l, *dirFlag)
+		destroyer, err := destroy.New(logrus.StandardLogger(), *dirFlag)
 		if err != nil {
-			log.Fatalf("failed to create destroyer: %v", err)
-			os.Exit(1)
+			logrus.Fatalf("Failed while preparing to destroy cluster: %v", err)
 		}
 		if err := destroyer.Run(); err != nil {
-			log.Fatalf("destroy failed: %v", err)
-			os.Exit(1)
+			logrus.Fatalf("Failed to destroy cluster: %v", err)
 		}
-
 	}
-
 }

pkg/asset/cluster/cluster.go

@@ -7,7 +7,7 @@ import (
 	"os"
 	"path/filepath"
 
-	log "github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus"
 
 	"github.com/openshift/installer/data"
 	"github.com/openshift/installer/pkg/asset"
@@ -73,6 +73,8 @@ func (c *Cluster) Generate(parents map[asset.Asset]*asset.State) (*asset.State,
 		return nil, err
 	}
 
+	logrus.Infof("Using Terraform to create cluster...")
+
 	// This runs the terraform in a temp directory, the tfstate file will be returned
 	// to the asset store to persist it on the disk.
 	if err := terraform.Init(tmpDir); err != nil {
@@ -81,22 +83,24 @@ func (c *Cluster) Generate(parents map[asset.Asset]*asset.State) (*asset.State,
 
 	stateFile, err := terraform.Apply(tmpDir)
 	if err != nil {
-		// we should try to fetch the terraform state file.
-		log.Errorf("terraform failed: %v", err)
+		err = fmt.Errorf("terraform failed: %v", err)
 	}
 
-	data, err := ioutil.ReadFile(stateFile)
-	if err != nil {
-		return nil, fmt.Errorf("failed to read tfstate file %q: %v", stateFile, err)
+	data, err2 := ioutil.ReadFile(stateFile)
+	if err2 != nil {
+		if err == nil {
+			err = err2
+		} else {
+			logrus.Errorf("Failed to read tfstate (%q): %v", stateFile, err2)
+		}
 	}
 
-	// TODO(yifan): Use the kubeconfig to verify the cluster is up.
 	return &asset.State{
 		Contents: []asset.Content{
 			{
 				Name: stateFileName,
 				Data: data,
 			},
 		},
-	}, nil
+	}, err
 }

pkg/asset/store.go

@@ -25,7 +25,7 @@ func (s *StoreImpl) Fetch(asset Asset) (*State, error) {
 }
 
 func (s *StoreImpl) fetch(asset Asset, indent string) (*State, error) {
-	logrus.Infof("%sFetching %s...", indent, asset.Name())
+	logrus.Debugf("%sFetching %s...", indent, asset.Name())
 	state, ok := s.assets[asset]
 	if ok {
 		logrus.Debugf("%sFound %s...", indent, asset.Name())

pkg/destroy/aws.go

@@ -1,27 +1,18 @@
 package destroy
 
 import (
-	"os"
-
 	atd "github.com/openshift/hive/contrib/pkg/awstagdeprovision"
 	"github.com/openshift/installer/pkg/types"
-	log "github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus"
 )
 
 // NewAWS returns an AWS destroyer from ClusterMetadata.
-func NewAWS(level log.Level, metadata *types.ClusterMetadata) (Destroyer, error) {
+func NewAWS(logger logrus.FieldLogger, metadata *types.ClusterMetadata) (Destroyer, error) {
 	return &atd.ClusterUninstaller{
 		Filters:     metadata.ClusterPlatformMetadata.AWS.Identifier,
 		Region:      metadata.ClusterPlatformMetadata.AWS.Region,
 		ClusterName: metadata.ClusterName,
-		Logger: log.NewEntry(&log.Logger{
-			Out: os.Stdout,
-			Formatter: &log.TextFormatter{
-				FullTimestamp: true,
-			},
-			Hooks: make(log.LevelHooks),
-			Level: level,
-		}),
+		Logger:      logger,
 	}, nil
 }
 

pkg/destroy/destroyer.go

@@ -6,7 +6,7 @@ import (
 	"io/ioutil"
 	"path/filepath"
 
-	log "github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus"
 
 	"github.com/openshift/installer/pkg/asset/metadata"
 	"github.com/openshift/installer/pkg/types"
@@ -19,13 +19,13 @@ type Destroyer interface {
 }
 
 // NewFunc is an interface for creating platform-specific destroyers.
-type NewFunc func(level log.Level, metadata *types.ClusterMetadata) (Destroyer, error)
+type NewFunc func(logger logrus.FieldLogger, metadata *types.ClusterMetadata) (Destroyer, error)
 
 // Registry maps ClusterMetadata.Platform() to per-platform Destroyer creators.
 var Registry = make(map[string]NewFunc)
 
 // New returns a Destroyer based on `metadata.json` in `rootDir`.
-func New(level log.Level, rootDir string) (Destroyer, error) {
+func New(logger logrus.FieldLogger, rootDir string) (Destroyer, error) {
 	path := filepath.Join(rootDir, metadata.MetadataFilename)
 	raw, err := ioutil.ReadFile(filepath.Join(rootDir, metadata.MetadataFilename))
 	if err != nil {
@@ -46,5 +46,5 @@ func New(level log.Level, rootDir string) (Destroyer, error) {
 	if !ok {
 		return nil, fmt.Errorf("no destroyers registered for %q", platform)
 	}
-	return creator(level, cmetadata)
+	return creator(logger, cmetadata)
 }

pkg/destroy/libvirt/libvirt_prefix_deprovision.go

@@ -10,7 +10,7 @@ import (
 	libvirt "github.com/libvirt/libvirt-go"
 	"github.com/openshift/installer/pkg/destroy"
 	"github.com/openshift/installer/pkg/types"
-	log "github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus"
 	"k8s.io/apimachinery/pkg/util/wait"
 )
 
@@ -44,13 +44,13 @@ var AlwaysTrueFilter = func() filterFunc {
 // deleteFunc type is the interface a function needs to implement to be called as a goroutine.
 // The (bool, error) return type mimics wait.ExponentialBackoff where the bool indicates successful
 // completion, and the error is for unrecoverable errors.
-type deleteFunc func(conn *libvirt.Connect, filter filterFunc, logger log.FieldLogger) (bool, error)
+type deleteFunc func(conn *libvirt.Connect, filter filterFunc, logger logrus.FieldLogger) (bool, error)
 
 // ClusterUninstaller holds the various options for the cluster we want to delete.
 type ClusterUninstaller struct {
 	LibvirtURI string
 	Filter     filterFunc
-	Logger     log.FieldLogger
+	Logger     logrus.FieldLogger
 }
 
 // Run is the entrypoint to start the uninstall process
@@ -80,7 +80,7 @@ func (o *ClusterUninstaller) Run() error {
 	return nil
 }
 
-func deleteRunner(deleteFuncName string, dFunction deleteFunc, conn *libvirt.Connect, filter filterFunc, logger log.FieldLogger, channel chan string) {
+func deleteRunner(deleteFuncName string, dFunction deleteFunc, conn *libvirt.Connect, filter filterFunc, logger logrus.FieldLogger, channel chan string) {
 	backoffSettings := wait.Backoff{
 		Duration: time.Second * 10,
 		Factor:   1.3,
@@ -108,7 +108,7 @@ func populateDeleteFuncs(funcs map[string]deleteFunc) {
 	funcs["deleteNetwork"] = deleteNetwork
 }
 
-func deleteDomains(conn *libvirt.Connect, filter filterFunc, logger log.FieldLogger) (bool, error) {
+func deleteDomains(conn *libvirt.Connect, filter filterFunc, logger logrus.FieldLogger) (bool, error) {
 	logger.Debug("Deleting libvirt domains")
 	defer logger.Debugf("Exiting deleting libvirt domains")
 
@@ -143,7 +143,7 @@ func deleteDomains(conn *libvirt.Connect, filter filterFunc, logger log.FieldLog
 	return true, nil
 }
 
-func deleteVolumes(conn *libvirt.Connect, filter filterFunc, logger log.FieldLogger) (bool, error) {
+func deleteVolumes(conn *libvirt.Connect, filter filterFunc, logger logrus.FieldLogger) (bool, error) {
 	logger.Debug("Deleting libvirt volumes")
 	defer logger.Debugf("Exiting deleting libvirt volumes")
 
@@ -209,7 +209,7 @@ func deleteVolumes(conn *libvirt.Connect, filter filterFunc, logger log.FieldLog
 	return true, nil
 }
 
-func deleteNetwork(conn *libvirt.Connect, filter filterFunc, logger log.FieldLogger) (bool, error) {
+func deleteNetwork(conn *libvirt.Connect, filter filterFunc, logger logrus.FieldLogger) (bool, error) {
 	logger.Debug("Deleting libvirt network")
 	defer logger.Debugf("Exiting deleting libvirt network")
 
@@ -245,17 +245,10 @@ func deleteNetwork(conn *libvirt.Connect, filter filterFunc, logger log.FieldLog
 }
 
 // New returns libvirt Uninstaller from ClusterMetadata.
-func New(level log.Level, metadata *types.ClusterMetadata) (destroy.Destroyer, error) {
+func New(logger logrus.FieldLogger, metadata *types.ClusterMetadata) (destroy.Destroyer, error) {
 	return &ClusterUninstaller{
 		LibvirtURI: metadata.ClusterPlatformMetadata.Libvirt.URI,
 		Filter:     AlwaysTrueFilter(), //TODO: change to ClusterNamePrefixFilter when all resources are prefixed.
-		Logger: log.NewEntry(&log.Logger{
-			Out: os.Stdout,
-			Formatter: &log.TextFormatter{
-				FullTimestamp: true,
-			},
-			Hooks: make(log.LevelHooks),
-			Level: level,
-		}),
+		Logger:     logger,
 	}, nil
 }

pkg/terraform/executor.go

@@ -7,6 +7,8 @@ import (
 	"os/exec"
 	"path/filepath"
 	"runtime"
+
+	"github.com/sirupsen/logrus"
 )
 
 // executor enables calling Terraform from Go, across platforms, with any
@@ -58,10 +60,14 @@ func (ex *executor) execute(clusterDir string, args ...string) error {
 	}
 
 	cmd := exec.Command(ex.binaryPath, args...)
-	cmd.Stdin = os.Stdin
-	cmd.Stdout = os.Stdout
-	cmd.Stderr = os.Stderr
 	cmd.Dir = clusterDir
+	if logrus.GetLevel() == logrus.DebugLevel {
+		cmd.Stdin = os.Stdin
+		cmd.Stdout = os.Stdout
+		cmd.Stderr = os.Stderr
+	}
+
+	logrus.Debugf("Running %#v...", cmd)
 
 	// Start Terraform.
 	return cmd.Run()

pkg/terraform/terraform.go

@@ -19,8 +19,9 @@ func terraformExec(clusterDir string, args ...string) error {
 	return nil
 }
 
-// Apply runs "terraform apply" in the given directory.
-// It returns the absolute path of the tfstate file.
+// Apply runs "terraform apply" in the given directory. It returns the absolute
+// path of the tfstate file, rooted in the specified directory, along with any
+// errors from Terraform.
 func Apply(dir string, extraArgs ...string) (string, error) {
 	stateFileName := "terraform.tfstate"
 	defaultArgs := []string{

pkg/types/config/libvirt/cache.go

@@ -11,6 +11,7 @@ import (
 
 	"github.com/gregjones/httpcache"
 	"github.com/gregjones/httpcache/diskcache"
+	"github.com/sirupsen/logrus"
 )
 
 // UseCachedImage leaves non-file:// image URIs unalterered.
@@ -28,6 +29,8 @@ func (libvirt *Libvirt) UseCachedImage() (err error) {
 		return nil
 	}
 
+	logrus.Infof("Fetching OS image...")
+
 	// FIXME: Use os.UserCacheDir() once we bump to Go 1.11
 	// baseCacheDir, err := os.UserCacheDir()
 	// if err != nil {

pkg/types/config/validate.go

@@ -13,7 +13,7 @@ import (
 	"github.com/openshift/installer/pkg/types/config/aws"
 
 	"github.com/coreos/tectonic-config/config/tectonic-network"
-	log "github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus"
 )
 
 const (
@@ -216,15 +216,11 @@ func (c *Cluster) validateNetworkType() error {
 // a single error for convenience.
 func (c *Cluster) ValidateAndLog() error {
 	if errs := c.Validate(); len(errs) != 0 {
-		s := ""
-		if len(errs) != 1 {
-			s = "s"
-		}
-		log.Errorf("Found %d error%s in the cluster definition:", len(errs), s)
+		logrus.Errorf("Found %d error(s) in the cluster definition:", len(errs))
 		for i, err := range errs {
-			log.Errorf("error %d: %v", i+1, err)
+			logrus.Errorf("  Error %d: %v", i+1, err)
 		}
-		return fmt.Errorf("found %d cluster definition error%s", len(errs), s)
+		return fmt.Errorf("found %d cluster definition error(s)", len(errs))
 	}
 	return nil
 }