Merge pull request #10425 from bharathkkb/fix-multiple-log-files

Generate one log file per minikube command

cmd/minikube/main.go

@@ -18,6 +18,8 @@ package main
 
 import (
 	"bytes"
+	"crypto/sha1"
+	"encoding/hex"
 	"flag"
 	"fmt"
 	"log"
@@ -126,6 +128,39 @@ func (lb machineLogBridge) Write(b []byte) (n int, err error) {
 	return len(b), nil
 }
 
+// checkLogFileMaxSize checks if a file's size is greater than or equal to max size in KB
+func checkLogFileMaxSize(file string, maxSizeKB int64) bool {
+	f, err := os.Stat(file)
+	if err != nil {
+		return false
+	}
+	kb := (f.Size() / 1024)
+	return kb >= maxSizeKB
+}
+
+// logFileName generates a default logfile name in the form minikube_<argv[1]>_<hash>_<count>.log from args
+func logFileName(dir string, logIdx int64) string {
+	h := sha1.New()
+	for _, s := range os.Args {
+		if _, err := h.Write([]byte(s)); err != nil {
+			klog.Warningf("Unable to add arg %s to log filename hash: %v", s, err)
+		}
+	}
+	hs := hex.EncodeToString(h.Sum(nil))
+	var logfilePath string
+	// check if subcommand specified
+	if len(os.Args) < 2 {
+		logfilePath = filepath.Join(dir, fmt.Sprintf("minikube_%s_%d.log", hs, logIdx))
+	} else {
+		logfilePath = filepath.Join(dir, fmt.Sprintf("minikube_%s_%s_%d.log", os.Args[1], hs, logIdx))
+	}
+	// if log has reached max size 1M, generate new logfile name by incrementing count
+	if checkLogFileMaxSize(logfilePath, 1024) {
+		return logFileName(dir, logIdx+1)
+	}
+	return logfilePath
+}
+
 // setFlags sets the flags
 func setFlags(parse bool) {
 	// parse flags beyond subcommand - get aroung go flag 'limitations':
@@ -151,6 +186,20 @@ func setFlags(parse bool) {
 	}
 	setLastStartFlags()
 
+	// set default log_file name but don't override user's preferences
+	if !pflag.CommandLine.Changed("log_file") {
+		// default log_file dir to $TMP
+		dir := os.TempDir()
+		// set log_dir to user input if specified
+		if pflag.CommandLine.Changed("log_dir") && pflag.Lookup("log_dir").Value.String() != "" {
+			dir = pflag.Lookup("log_dir").Value.String()
+		}
+		l := logFileName(dir, 0)
+		if err := pflag.Set("log_file", l); err != nil {
+			klog.Warningf("Unable to set default flag value for log_file: %v", err)
+		}
+	}
+
 	// make sure log_dir exists if log_file is not also set - the log_dir is mutually exclusive with the log_file option
 	// ref: https://github.com/kubernetes/klog/blob/52c62e3b70a9a46101f33ebaf0b100ec55099975/klog.go#L491
 	if pflag.Lookup("log_file") != nil && pflag.Lookup("log_file").Value.String() == "" &&

site/content/en/docs/handbook/troubleshooting.md

@@ -19,15 +19,15 @@ Example:
 
 ## Post-mortem minikube debug logs
 
-minikube stores post-mortem INFO logs in the temporary directory of your system. On macOS or Linux, it's easy to get a list of recent INFO logs:
+minikube stores post-mortem logs in the temporary directory of your system. One log file is created per subcommand and any subsequent invocations of the subcommand with the same args will append to the same file. If the log file has exceeded 1MB in size, a new log file is created. On macOS or Linux, it's easy to get a list of recent logs:
 
 ```shell
-find $TMPDIR -mtime -1 -type f -name "*minikube*INFO*" -ls  2>/dev/null
+find $TMPDIR -mtime -1 -type f -name "*minikube*" -ls  2>/dev/null
 ```
 
-For instance, this shows:
+For instance after running `minikube start`, the above comamnd will show:
 
-`-rw-r--r-- 1 user  grp  718 Aug 18 12:40 /var/folders/n1/qxvd9kc/T//minikube.mac.user.log.INFO.20200818-124017.63501`
+`-rw-r--r-- 1 user  grp  718 Aug 18 12:40 /var/folders/n1/qxvd9kc/T//minikube_start_dc950831e1a232e0318a6d6ca82aaf4f4a8a048b_0.log`
 
 These are plain text log files: you may rename them to "<filename>.log" and then drag/drop them into a GitHub issue for further analysis by the minikube team. You can quickly inspect the final lines of any of these logs via:
   

test/integration/error_spam_test.go

@@ -20,7 +20,10 @@ package integration
 
 import (
 	"context"
+	"fmt"
+	"os"
 	"os/exec"
+	"path/filepath"
 	"regexp"
 	"strings"
 	"testing"
@@ -104,4 +107,103 @@ func TestErrorSpam(t *testing.T) {
 			t.Errorf("missing kubeadm init sub-step %q", step)
 		}
 	}
+
+	logTests := []struct {
+		command          string
+		args             []string
+		runCount         int // number of times to run command
+		expectedLogFiles int // number of logfiles expected after running command runCount times
+	}{
+		{
+			command:          "start",
+			args:             []string{"--dry-run", "--log_dir", os.TempDir()},
+			runCount:         120, // calling this 120 times should create 2 files with 1 greater than 1M
+			expectedLogFiles: 2,
+		},
+		{
+			command:          "status",
+			runCount:         100,
+			expectedLogFiles: 1,
+		}, {
+			command:          "pause",
+			runCount:         5,
+			expectedLogFiles: 1,
+		}, {
+			command:          "unpause",
+			runCount:         1,
+			expectedLogFiles: 1,
+		}, {
+			command:          "stop",
+			runCount:         1,
+			expectedLogFiles: 1,
+		},
+	}
+
+	for _, test := range logTests {
+		t.Run(test.command, func(t *testing.T) {
+			args := []string{test.command, "-p", profile}
+			args = append(args, test.args...)
+			// before starting the test, ensure no other logs from the current command are written
+			logFiles, err := getLogFiles(test.command)
+			if err != nil {
+				t.Errorf("failed to find tmp log files: command %s : %v", test.command, err)
+			}
+			cleanupLogFiles(t, logFiles)
+			// run command runCount times
+			for i := 0; i < test.runCount; i++ {
+				rr, err := Run(t, exec.CommandContext(ctx, Target(), args...))
+				if err != nil {
+					t.Fatalf("%q failed: %v", rr.Command(), err)
+				}
+			}
+			// get log files generated above
+			logFiles, err = getLogFiles(test.command)
+			if err != nil {
+				t.Errorf("failed to find tmp log files: command %s : %v", test.command, err)
+			}
+			// cleanup generated logfiles
+			defer cleanupLogFiles(t, logFiles)
+			// if not the expected number of files, throw err
+			if len(logFiles) != test.expectedLogFiles {
+				t.Errorf("failed to find expected number of log files: cmd %s: expected: %d got %d", test.command, test.expectedLogFiles, len(logFiles))
+			}
+			// if more than 1 logfile is expected, only one file should be less than 1M
+			if test.expectedLogFiles > 1 {
+				foundSmall := false
+				maxSize := 1024 * 1024 // 1M
+				for _, logFile := range logFiles {
+					isSmall := int(logFile.Size()) < maxSize
+					if isSmall && !foundSmall {
+						foundSmall = true
+					} else if isSmall && foundSmall {
+						t.Errorf("expected to find only one file less than 1MB: cmd %s:", test.command)
+					}
+				}
+			}
+		})
+
+	}
+}
+
+// getLogFiles returns logfiles corresponding to cmd
+func getLogFiles(cmdName string) ([]os.FileInfo, error) {
+	var logFiles []os.FileInfo
+	err := filepath.Walk(os.TempDir(), func(path string, info os.FileInfo, err error) error {
+		if strings.Contains(info.Name(), fmt.Sprintf("minikube_%s", cmdName)) {
+			logFiles = append(logFiles, info)
+		}
+		return nil
+	})
+	return logFiles, err
+}
+
+// cleanupLogFiles removes logfiles generated during testing
+func cleanupLogFiles(t *testing.T, logFiles []os.FileInfo) {
+	for _, logFile := range logFiles {
+		logFilePath := filepath.Join(os.TempDir(), logFile.Name())
+		t.Logf("Cleaning up logfile %s ...", logFilePath)
+		if err := os.Remove(logFilePath); err != nil {
+			t.Errorf("failed to cleanup log file: %s : %v", logFilePath, err)
+		}
+	}
 }