Merge pull request #5382 from tstromberg/too-much-logs

Redirect machine driver logs to glog, reduce log spam elsewhere

cmd/minikube/cmd/root.go

@@ -19,13 +19,11 @@ package cmd
 import (
 	goflag "flag"
 	"fmt"
-	"io/ioutil"
 	"os"
 	"runtime"
 	"strings"
 
 	"github.com/docker/machine/libmachine"
-	"github.com/docker/machine/libmachine/log"
 	"github.com/golang/glog"
 	"github.com/pkg/errors"
 	"github.com/spf13/cobra"
@@ -71,17 +69,6 @@ var RootCmd = &cobra.Command{
 			}
 		}
 
-		// Log level 3 or greater enables libmachine logs
-		if !glog.V(3) {
-			log.SetOutWriter(ioutil.Discard)
-			log.SetErrWriter(ioutil.Discard)
-		}
-
-		// Log level 7 or greater enables debug level logs
-		if glog.V(7) {
-			log.SetDebug(true)
-		}
-
 		logDir := pflag.Lookup("log_dir")
 		if !logDir.Changed {
 			if err := logDir.Value.Set(constants.MakeMiniPath("logs")); err != nil {

cmd/minikube/main.go

@@ -21,12 +21,15 @@ import (
 	"fmt"
 	"log"
 	"os"
+	"regexp"
 	"strconv"
 
 	// initflag must be imported before any other minikube pkg.
 	// Fix for https://github.com/kubernetes/minikube/issues/4866
 	_ "k8s.io/minikube/pkg/initflag"
 
+	mlog "github.com/docker/machine/libmachine/log"
+
 	"github.com/golang/glog"
 	"github.com/pkg/profile"
 	"k8s.io/minikube/cmd/minikube/cmd"
@@ -38,8 +41,13 @@ import (
 
 const minikubeEnableProfile = "MINIKUBE_ENABLE_PROFILING"
 
+var (
+	machineLogErrorRe   = regexp.MustCompile(`(?i) (failed|error|fatal)`)
+	machineLogWarningRe = regexp.MustCompile(`(?i)warning`)
+)
+
 func main() {
-	captureStdLogMessages()
+	bridgeLogMessages()
 	defer glog.Flush()
 
 	if os.Getenv(minikubeEnableProfile) == "1" {
@@ -53,16 +61,18 @@ func main() {
 	cmd.Execute()
 }
 
-// captureStdLogMessages arranges for messages written to the Go "log" package's to appear in glog
-func captureStdLogMessages() {
+// bridgeLogMessages bridges non-glog logs into glog
+func bridgeLogMessages() {
 	log.SetFlags(log.Lshortfile)
-	log.SetOutput(logBridge{})
+	log.SetOutput(stdLogBridge{})
+	mlog.SetErrWriter(machineLogBridge{})
+	mlog.SetOutWriter(machineLogBridge{})
 }
 
-type logBridge struct{}
+type stdLogBridge struct{}
 
 // Write parses the standard logging line and passes its components to glog
-func (lb logBridge) Write(b []byte) (n int, err error) {
+func (lb stdLogBridge) Write(b []byte) (n int, err error) {
 	// Split "d.go:23: message" into "d.go", "23", and "message".
 	parts := bytes.SplitN(b, []byte{':'}, 3)
 	if len(parts) != 3 || len(parts[0]) < 1 || len(parts[2]) < 1 {
@@ -80,3 +90,18 @@ func (lb logBridge) Write(b []byte) (n int, err error) {
 	glog.Infof("stdlog: %s:%d %s", file, line, text)
 	return len(b), nil
 }
+
+// libmachine log bridge
+type machineLogBridge struct{}
+
+// Write passes machine driver logs to glog
+func (lb machineLogBridge) Write(b []byte) (n int, err error) {
+	if machineLogErrorRe.Match(b) {
+		glog.Errorf("libmachine: %s", b)
+	} else if machineLogWarningRe.Match(b) {
+		glog.Warningf("libmachine: %s", b)
+	} else {
+		glog.Infof("libmachine: %s", b)
+	}
+	return len(b), nil
+}

pkg/minikube/command/ssh_runner.go

@@ -81,13 +81,13 @@ func teeSSH(s *ssh.Session, cmd string, outB io.Writer, errB io.Writer) error {
 	wg.Add(2)
 
 	go func() {
-		if err := util.TeePrefix(util.ErrPrefix, errPipe, errB, glog.V(2).Infof); err != nil {
+		if err := util.TeePrefix(util.ErrPrefix, errPipe, errB, glog.V(8).Infof); err != nil {
 			glog.Errorf("tee stderr: %v", err)
 		}
 		wg.Done()
 	}()
 	go func() {
-		if err := util.TeePrefix(util.OutPrefix, outPipe, outB, glog.V(2).Infof); err != nil {
+		if err := util.TeePrefix(util.OutPrefix, outPipe, outB, glog.V(8).Infof); err != nil {
 			glog.Errorf("tee stdout: %v", err)
 		}
 		wg.Done()

test/integration/docker_test.go

@@ -37,7 +37,7 @@ func TestDockerFlags(t *testing.T) {
 	defer CleanupWithLogs(t, profile, cancel)
 
 	// Use the most verbose logging for the simplest test. If it fails, something is very wrong.
-	args := append([]string{"start", "-p", profile, "--wait=false", "--docker-env=FOO=BAR", "--docker-env=BAZ=BAT", "--docker-opt=debug", "--docker-opt=icc=true", "--alsologtostderr", "-v=8"}, StartArgs()...)
+	args := append([]string{"start", "-p", profile, "--wait=false", "--docker-env=FOO=BAR", "--docker-env=BAZ=BAT", "--docker-opt=debug", "--docker-opt=icc=true", "--alsologtostderr", "-v=5"}, StartArgs()...)
 	rr, err := Run(t, exec.CommandContext(ctx, Target(), args...))
 	if err != nil {
 		t.Errorf("%s failed: %v", rr.Args, err)