Switch logging from glog to logrus

Improve interactive output experience by switching to a logging
library (logrus) that allows customising the output format.

This also removes the glog command line flags.  Replaced with a
simpler `--verbose`/`-v` option:
- quiet by default (warnings and errors only)
- `-v` for progress info
- `-vv` for debug

Fixes #34

cmd/delete.go

@@ -4,7 +4,7 @@ import (
 	"fmt"
 	"sort"
 
-	"github.com/golang/glog"
+	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 	"k8s.io/client-go/pkg/api/errors"
 	"k8s.io/client-go/pkg/api/v1"
@@ -57,7 +57,7 @@ var deleteCmd = &cobra.Command{
 
 		for _, obj := range objs {
 			desc := fmt.Sprintf("%s/%s", obj.GetKind(), fqName(obj))
-			glog.Info("Deleting ", desc)
+			log.Info("Deleting ", desc)
 
 			c, err := clientForResource(clientpool, disco, obj, defaultNs)
 			if err != nil {
@@ -69,7 +69,7 @@ var deleteCmd = &cobra.Command{
 				return fmt.Errorf("Error deleting %s: %s", desc, err)
 			}
 
-			glog.V(2).Info("Deleted object: ", obj)
+			log.Debugf("Deleted object: ", obj)
 		}
 
 		return nil

cmd/diff.go

@@ -6,8 +6,8 @@ import (
 	"os"
 	"sort"
 
-	"github.com/golang/glog"
 	"github.com/mattn/go-isatty"
+	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 	"github.com/yudai/gojsondiff"
 	"github.com/yudai/gojsondiff/formatter"
@@ -45,7 +45,7 @@ var diffCmd = &cobra.Command{
 
 		for _, obj := range objs {
 			desc := fmt.Sprintf("%s/%s", obj.GetKind(), fqName(obj))
-			glog.V(2).Info("Fetching ", desc)
+			log.Debugf("Fetching ", desc)
 
 			c, err := clientForResource(clientpool, disco, obj, defaultNs)
 			if err != nil {
@@ -54,7 +54,7 @@ var diffCmd = &cobra.Command{
 
 			liveObj, err := c.Get(obj.GetName())
 			if err != nil && errors.IsNotFound(err) {
-				glog.V(2).Infof("%s doesn't exist on the server", desc)
+				log.Debugf("%s doesn't exist on the server", desc)
 				liveObj = nil
 			} else if err != nil {
 				return fmt.Errorf("Error fetching %s: %v", desc, err)

cmd/root.go

@@ -5,15 +5,17 @@ import (
 	"encoding/json"
 	goflag "flag"
 	"fmt"
+	"io"
 	"io/ioutil"
 	"net/http"
 	"os"
 	"path/filepath"
 	"strings"
 
-	"github.com/golang/glog"
+	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 	jsonnet "github.com/strickyak/jsonnet_cgo"
+	"golang.org/x/crypto/ssh/terminal"
 	"k8s.io/client-go/discovery"
 	"k8s.io/client-go/dynamic"
 	"k8s.io/client-go/pkg/api/unversioned"
@@ -24,6 +26,7 @@ import (
 )
 
 const (
+	flagVerbose    = "verbose"
 	flagJpath      = "jpath"
 	flagExtVar     = "ext-str"
 	flagExtVarFile = "ext-str-file"
@@ -36,6 +39,7 @@ const (
 var clientConfig clientcmd.ClientConfig
 
 func init() {
+	RootCmd.PersistentFlags().CountP(flagVerbose, "v", "Increase verbosity. May be given multiple times.")
 	RootCmd.PersistentFlags().StringP(flagJpath, "J", "", "Additional jsonnet library search path")
 	RootCmd.PersistentFlags().StringSliceP(flagExtVar, "V", nil, "Values of external variables")
 	RootCmd.PersistentFlags().StringSlice(flagExtVarFile, nil, "Read external variable from a file")
@@ -53,8 +57,6 @@ func init() {
 	clientcmd.BindOverrideFlags(&overrides, RootCmd.PersistentFlags(), kflags)
 	clientConfig = clientcmd.NewInteractiveDeferredLoadingClientConfig(loadingRules, &overrides, os.Stdin)
 
-	// Standard goflags (glog in particular)
-	RootCmd.PersistentFlags().AddGoFlagSet(goflag.CommandLine)
 	RootCmd.PersistentFlags().Set("logtostderr", "true")
 }
 
@@ -64,12 +66,78 @@ var RootCmd = &cobra.Command{
 	Short:         "Synchronise Kubernetes resources with config files",
 	SilenceErrors: true,
 	SilenceUsage:  true,
-	PersistentPreRun: func(cmd *cobra.Command, args []string) {
+	PersistentPreRunE: func(cmd *cobra.Command, args []string) error {
 		goflag.CommandLine.Parse([]string{})
-		glog.CopyStandardLogTo("INFO")
+		flags := cmd.Flags()
+		out := cmd.OutOrStderr()
+		log.SetOutput(out)
+
+		logFmt := NewLogFormatter(out)
+		log.SetFormatter(logFmt)
+
+		verbosity, err := flags.GetCount(flagVerbose)
+		if err != nil {
+			return err
+		}
+		log.SetLevel(logLevel(verbosity))
+
+		return nil
 	},
 }
 
+func logLevel(verbosity int) log.Level {
+	switch verbosity {
+	case 0:
+		return log.WarnLevel
+	case 1:
+		return log.InfoLevel
+	default:
+		return log.DebugLevel
+	}
+}
+
+type logFormatter struct {
+	escapes  *terminal.EscapeCodes
+	colorise bool
+}
+
+// NewLogFormatter creates a new log.Formatter customised for writer
+func NewLogFormatter(out io.Writer) log.Formatter {
+	var ret = logFormatter{}
+	if f, ok := out.(*os.File); ok {
+		ret.colorise = terminal.IsTerminal(int(f.Fd()))
+		ret.escapes = terminal.NewTerminal(f, "").Escape
+	}
+	return &ret
+}
+
+func (f *logFormatter) levelEsc(level log.Level) []byte {
+	switch level {
+	case log.DebugLevel:
+		return []byte{}
+	case log.WarnLevel:
+		return f.escapes.Yellow
+	case log.ErrorLevel, log.FatalLevel, log.PanicLevel:
+		return f.escapes.Red
+	default:
+		return f.escapes.Blue
+	}
+}
+
+func (f *logFormatter) Format(e *log.Entry) ([]byte, error) {
+	buf := bytes.Buffer{}
+	if f.colorise {
+		buf.Write(f.levelEsc(e.Level))
+		fmt.Fprintf(&buf, "%-5s ", strings.ToUpper(e.Level.String()))
+		buf.Write(f.escapes.Reset)
+	}
+
+	buf.WriteString(strings.TrimSpace(e.Message))
+	buf.WriteString("\n")
+
+	return buf.Bytes(), nil
+}
+
 // JsonnetVM constructs a new jsonnet.VM, according to command line
 // flags
 func JsonnetVM(cmd *cobra.Command) (*jsonnet.VM, error) {
@@ -78,7 +146,7 @@ func JsonnetVM(cmd *cobra.Command) (*jsonnet.VM, error) {
 
 	jpath := os.Getenv("KUBECFG_JPATH")
 	for _, p := range filepath.SplitList(jpath) {
-		glog.V(2).Infoln("Adding jsonnet search path", p)
+		log.Debugln("Adding jsonnet search path", p)
 		vm.JpathAdd(p)
 	}
 
@@ -87,7 +155,7 @@ func JsonnetVM(cmd *cobra.Command) (*jsonnet.VM, error) {
 		return nil, err
 	}
 	for _, p := range filepath.SplitList(jpath) {
-		glog.V(2).Infoln("Adding jsonnet search path", p)
+		log.Debugln("Adding jsonnet search path", p)
 		vm.JpathAdd(p)
 	}
 
@@ -188,7 +256,7 @@ func buildResolver(cmd *cobra.Command) (utils.Resolver, error) {
 		ret.OnErr = func(error) error { return nil }
 	case "warn":
 		ret.OnErr = func(err error) error {
-			glog.Warning(err.Error())
+			log.Warning(err.Error())
 			return nil
 		}
 	case "error":
@@ -280,7 +348,7 @@ func serverResourceForGroupVersionKind(disco discovery.DiscoveryInterface, gvk u
 
 	for _, r := range resources.APIResources {
 		if r.Kind == gvk.Kind {
-			glog.V(4).Infof("Chose API '%s' for %s", r.Name, gvk)
+			log.Debugf("Chose API '%s' for %s", r.Name, gvk)
 			return &r, nil
 		}
 	}
@@ -306,7 +374,7 @@ func clientForResource(pool dynamic.ClientPool, disco discovery.DiscoveryInterfa
 		namespace = defNs
 	}
 
-	glog.V(4).Infof("Fetching client for %s namespace=%s", resource, namespace)
+	log.Debugf("Fetching client for %s namespace=%s", resource, namespace)
 	rc := client.Resource(resource, namespace)
 	return rc, nil
 }

cmd/update.go

@@ -5,7 +5,7 @@ import (
 	"fmt"
 	"sort"
 
-	"github.com/golang/glog"
+	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 	"k8s.io/client-go/pkg/api"
 	"k8s.io/client-go/pkg/api/errors"
@@ -54,7 +54,7 @@ var updateCmd = &cobra.Command{
 
 		for _, obj := range objs {
 			desc := fmt.Sprintf("%s/%s", obj.GetKind(), fqName(obj))
-			glog.Info("Updating ", desc)
+			log.Info("Updating ", desc)
 
 			c, err := clientForResource(clientpool, disco, obj, defaultNs)
 			if err != nil {
@@ -67,7 +67,7 @@ var updateCmd = &cobra.Command{
 			}
 			newobj, err := c.Patch(obj.GetName(), api.MergePatchType, asPatch)
 			if create && errors.IsNotFound(err) {
-				glog.Info(" Creating non-existent ", desc)
+				log.Info(" Creating non-existent ", desc)
 				newobj, err = c.Create(obj)
 			}
 			if err != nil {
@@ -75,7 +75,7 @@ var updateCmd = &cobra.Command{
 				return fmt.Errorf("Error updating %s: %s", desc, err)
 			}
 
-			glog.V(2).Info("Updated object: ", diff.ObjectDiff(obj, newobj))
+			log.Debug("Updated object: ", diff.ObjectDiff(obj, newobj))
 		}
 
 		return nil

main.go

 package main
 
 import (
-	"fmt"
-	"os"
+	log "github.com/sirupsen/logrus"
 
 	"github.com/ksonnet/kubecfg/cmd"
 )
@@ -14,7 +13,11 @@ func main() {
 	cmd.Version = version
 
 	if err := cmd.RootCmd.Execute(); err != nil {
-		fmt.Fprintln(os.Stderr, "Error:", err)
-		os.Exit(1)
+		// PersistentPreRunE may not have been run for early
+		// errors, like invalid command line flags.
+		logFmt := cmd.NewLogFormatter(log.StandardLogger().Out)
+		log.SetFormatter(logFmt)
+
+		log.Fatal(err.Error())
 	}
 }

utils/acquire.go

@@ -9,7 +9,7 @@ import (
 	"os"
 	"path/filepath"
 
-	"github.com/golang/glog"
+	log "github.com/sirupsen/logrus"
 	jsonnet "github.com/strickyak/jsonnet_cgo"
 	"k8s.io/client-go/pkg/runtime"
 	"k8s.io/client-go/pkg/util/yaml"
@@ -63,7 +63,6 @@ func yamlReader(r io.ReadCloser) ([]runtime.Object, error) {
 		} else if err != nil {
 			return nil, err
 		}
-		glog.V(4).Infof("Read %d bytes of YAML: %s", len(bytes), bytes)
 		if len(bytes) == 0 {
 			continue
 		}
@@ -71,7 +70,6 @@ func yamlReader(r io.ReadCloser) ([]runtime.Object, error) {
 		if err != nil {
 			return nil, err
 		}
-		glog.V(4).Infof("Converted to JSON: %s", jsondata)
 		obj, _, err := runtime.UnstructuredJSONScheme.Decode(jsondata, nil, nil)
 		if err != nil {
 			return nil, err
@@ -117,7 +115,7 @@ func jsonnetReader(vm *jsonnet.VM, path string) ([]runtime.Object, error) {
 		return nil, err
 	}
 
-	glog.V(4).Infof("jsonnet result is: %s\n", jsonstr)
+	log.Debugf("jsonnet result is: %s", jsonstr)
 
 	var top interface{}
 	if err = json.Unmarshal([]byte(jsonstr), &top); err != nil {

utils/registry.go

@@ -9,7 +9,7 @@ import (
 	"regexp"
 	"strings"
 
-	"github.com/golang/glog"
+	log "github.com/sirupsen/logrus"
 )
 
 var (
@@ -35,7 +35,7 @@ func NewRegistryClient(client *http.Client, url string) *Registry {
 func (r *Registry) ManifestDigest(reponame, tag string) (string, error) {
 	url := fmt.Sprintf("%s/v2/%s/manifests/%s", r.URL, reponame, tag)
 
-	glog.V(1).Infof("HEAD %s", url)
+	log.Debugf("HEAD %s", url)
 
 	req, err := http.NewRequest(http.MethodHead, url, nil)
 	if err != nil {
@@ -57,7 +57,7 @@ func (r *Registry) ManifestDigest(reponame, tag string) (string, error) {
 		return "", errors.New("No digest in response")
 	}
 
-	glog.V(1).Infof("Found digest %s", digest)
+	log.Debugf("Found digest %s", digest)
 	return digest, nil
 }
 
@@ -135,16 +135,16 @@ type authTransport struct {
 
 // RoundTrip is required for the http.RoundTripper interface
 func (t *authTransport) RoundTrip(req *http.Request) (*http.Response, error) {
-	glog.V(1).Infof("=> %v", req)
+	log.Debugf("=> %v", req)
 	resp, err := t.Transport.RoundTrip(req)
-	glog.V(1).Infof("<= err=%v resp=%v", err, resp)
+	log.Debugf("<= err=%v resp=%v", err, resp)
 	if err == nil && resp.StatusCode == http.StatusUnauthorized && matchesDomain(req.URL, t.HostDomain) {
 		schemes := parseAuthHeader(resp.Header)
 		for _, scheme := range schemes {
 			if scheme.Scheme == "basic" {
-				glog.V(2).Infof("Retrying with basic auth")
+				log.Debugf("Retrying with basic auth")
 				req.SetBasicAuth(t.Username, t.Password)
-				glog.V(1).Infof("=> %v", req)
+				log.Debugf("=> %v", req)
 				return t.Transport.RoundTrip(req)
 			}
 			if scheme.Scheme == "bearer" {
@@ -152,9 +152,9 @@ func (t *authTransport) RoundTrip(req *http.Request) (*http.Response, error) {
 				if err != nil {
 					return resp, err
 				}
-				glog.V(2).Infof("Retrying with bearer auth")
+				log.Debugf("Retrying with bearer auth")
 				req.Header.Set("Authorization", fmt.Sprintf("Bearer %s", token))
-				glog.V(1).Infof("=> %v", req)
+				log.Debugf("=> %v", req)
 				return t.Transport.RoundTrip(req)
 			}
 		}
@@ -187,7 +187,7 @@ func (t *authTransport) bearerAuth(realm, service, scope string) (string, error)
 		req.SetBasicAuth(t.Username, t.Password)
 	}
 
-	glog.V(3).Infof("Performing oauth request to %s", req.URL)
+	log.Debugf("Performing oauth request to %s", req.URL)
 	resp, err := t.Client.Do(req)
 	if err != nil {
 		return "", err
@@ -205,7 +205,7 @@ func (t *authTransport) bearerAuth(realm, service, scope string) (string, error)
 	if err := json.NewDecoder(resp.Body).Decode(&token); err != nil {
 		return "", err
 	}
-	glog.V(4).Infof("Got oauth token %q", token.Token)
+	log.Debugf("Got oauth token %q", token.Token)
 	t.tokenCache[cacheKey] = token.Token
 	return token.Token, err
 }