diff --git a/cmd/minikube/cmd/root.go b/cmd/minikube/cmd/root.go index 870518cddce9..6b7b13d08233 100644 --- a/cmd/minikube/cmd/root.go +++ b/cmd/minikube/cmd/root.go @@ -23,7 +23,6 @@ import ( "path/filepath" "runtime" "strings" - "time" "github.com/spf13/cobra" "github.com/spf13/pflag" @@ -84,8 +83,16 @@ var RootCmd = &cobra.Command{ // Execute adds all child commands to the root command sets flags appropriately. // This is called by main.main(). It only needs to happen once to the rootCmd. func Execute() { - defer audit.Log(time.Now()) - + auditID, err := audit.LogCommandStart() + if err != nil { + klog.Errorf("failed to log command start to audit: %v", err) + } + defer func() { + err := audit.LogCommandEnd(auditID) + if err != nil { + klog.Errorf("failed to log command end to audit: %v", err) + } + }() // Check whether this is a windows binary (.exe) running inisde WSL. if runtime.GOOS == "windows" && detect.IsMicrosoftWSL() { var found = false diff --git a/pkg/minikube/audit/audit.go b/pkg/minikube/audit/audit.go index eb4b0ead7199..e119429dad86 100644 --- a/pkg/minikube/audit/audit.go +++ b/pkg/minikube/audit/audit.go @@ -17,15 +17,20 @@ limitations under the License. package audit import ( + "bufio" + "encoding/json" + "fmt" "os" "os/user" "strings" "time" + "github.com/google/uuid" "github.com/spf13/pflag" "github.com/spf13/viper" - "k8s.io/klog/v2" "k8s.io/minikube/pkg/minikube/config" + "k8s.io/minikube/pkg/minikube/constants" + "k8s.io/minikube/pkg/minikube/localpath" "k8s.io/minikube/pkg/version" ) @@ -52,14 +57,67 @@ func args() string { } // Log details about the executed command. -func Log(startTime time.Time) { - if !shouldLog() { - return +func LogCommandStart() (string, error) { + if len(os.Args) < 2 || !shouldLog() { + return "", nil } - r := newRow(pflag.Arg(0), args(), userName(), version.GetVersion(), startTime, time.Now()) + id := uuid.New().String() + r := newRow(pflag.Arg(0), args(), userName(), version.GetVersion(), time.Now(), id) if err := appendToLog(r); err != nil { - klog.Warning(err) + return "", err } + return r.id, nil +} + +func LogCommandEnd(id string) error { + if id == "" { + return nil + } + if err := openAuditLog(); err != nil { + return err + } + defer closeAuditLog() + var logs []string + s := bufio.NewScanner(currentLogFile) + for s.Scan() { + logs = append(logs, s.Text()) + } + if err := s.Err(); err != nil { + return fmt.Errorf("failed to read from audit file: %v", err) + } + closeAuditLog() + rowSlice, err := logsToRows(logs) + if err != nil { + return fmt.Errorf("failed to convert logs to rows: %v", err) + } + auditContents := "" + var entriesNeedsToUpdate int + for _, v := range rowSlice { + if v.id == id { + v.endTime = time.Now().Format(constants.TimeFormat) + v.Data = v.toMap() + entriesNeedsToUpdate++ + } + auditLog, err := json.Marshal(v) + if err != nil { + return err + } + auditContents += string(auditLog) + "\n" + } + if entriesNeedsToUpdate == 0 { + return fmt.Errorf("failed to find a log row with id equals to %v", id) + } + // have to truncate the audit log while closed as Windows can't truncate an open file + if err := os.Truncate(localpath.AuditLog(), 0); err != nil { + return fmt.Errorf("failed to truncate audit log: %v", err) + } + if err := openAuditLog(); err != nil { + return err + } + if _, err = currentLogFile.Write([]byte(auditContents)); err != nil { + return fmt.Errorf("failed to write to audit log: %v", err) + } + return nil } // shouldLog returns if the command should be logged. @@ -74,7 +132,7 @@ func shouldLog() bool { } // commands that should not be logged. - no := []string{"status", "version"} + no := []string{"status", "version", "logs", "generate-docs"} a := pflag.Arg(0) for _, c := range no { if a == c { diff --git a/pkg/minikube/audit/audit_test.go b/pkg/minikube/audit/audit_test.go index e91f7d972a68..262ceac82135 100644 --- a/pkg/minikube/audit/audit_test.go +++ b/pkg/minikube/audit/audit_test.go @@ -20,7 +20,6 @@ import ( "os" "os/user" "testing" - "time" "github.com/spf13/pflag" "github.com/spf13/viper" @@ -177,7 +176,27 @@ func TestAudit(t *testing.T) { }) // Check if logging with limited args causes a panic - t.Run("Log", func(t *testing.T) { + t.Run("LogCommandStart", func(t *testing.T) { + oldArgs := os.Args + defer func() { os.Args = oldArgs }() + os.Args = []string{"minikube", "start"} + + oldCommandLine := pflag.CommandLine + defer func() { + pflag.CommandLine = oldCommandLine + pflag.Parse() + }() + mockArgs(t, os.Args) + auditID, err := LogCommandStart() + if auditID == "" { + t.Fatal("audit ID should not be empty") + } + if err != nil { + t.Fatal(err) + } + }) + + t.Run("LogCommandEnd", func(t *testing.T) { oldArgs := os.Args defer func() { os.Args = oldArgs }() os.Args = []string{"minikube"} @@ -188,8 +207,32 @@ func TestAudit(t *testing.T) { pflag.Parse() }() mockArgs(t, os.Args) + auditID, err := LogCommandStart() + if err != nil { + t.Fatal("start failed") + } + err = LogCommandEnd(auditID) - Log(time.Now()) + if err != nil { + t.Fatal(err) + } + }) + + t.Run("LogCommandEndNonExistingID", func(t *testing.T) { + oldArgs := os.Args + defer func() { os.Args = oldArgs }() + os.Args = []string{"minikube"} + + oldCommandLine := pflag.CommandLine + defer func() { + pflag.CommandLine = oldCommandLine + pflag.Parse() + }() + mockArgs(t, os.Args) + err := LogCommandEnd("non-existing-id") + if err == nil { + t.Fatal("function LogCommandEnd should return an error when a non-existing id is passed in it as an argument") + } }) } diff --git a/pkg/minikube/audit/logFile.go b/pkg/minikube/audit/logFile.go index 1762070f1e1f..437114aa8d11 100644 --- a/pkg/minikube/audit/logFile.go +++ b/pkg/minikube/audit/logFile.go @@ -20,6 +20,7 @@ import ( "fmt" "os" + "k8s.io/klog/v2" "k8s.io/minikube/pkg/minikube/localpath" "k8s.io/minikube/pkg/minikube/out/register" ) @@ -27,29 +28,35 @@ import ( // currentLogFile the file that's used to store audit logs var currentLogFile *os.File -// setLogFile sets the logPath and creates the log file if it doesn't exist. -func setLogFile() error { +// openAuditLog opens the audit log file or creates it if it doesn't exist. +func openAuditLog() error { lp := localpath.AuditLog() f, err := os.OpenFile(lp, os.O_APPEND|os.O_CREATE|os.O_RDWR, 0644) if err != nil { - return fmt.Errorf("unable to open %s: %v", lp, err) + return fmt.Errorf("failed to open the audit log: %v", err) } currentLogFile = f return nil } +// closeAuditLog closes the audit log file +func closeAuditLog() { + if err := currentLogFile.Close(); err != nil { + klog.Errorf("failed to close the audit log: %v", err) + } +} + // appendToLog appends the row to the log file. func appendToLog(row *row) error { - if currentLogFile == nil { - if err := setLogFile(); err != nil { - return err - } - } ce := register.CloudEvent(row, row.toMap()) bs, err := ce.MarshalJSON() if err != nil { return fmt.Errorf("error marshalling event: %v", err) } + if err := openAuditLog(); err != nil { + return err + } + defer closeAuditLog() if _, err := currentLogFile.WriteString(string(bs) + "\n"); err != nil { return fmt.Errorf("unable to write to audit log: %v", err) } diff --git a/pkg/minikube/audit/logFile_test.go b/pkg/minikube/audit/logFile_test.go index 617a43b8e0b6..916791108402 100644 --- a/pkg/minikube/audit/logFile_test.go +++ b/pkg/minikube/audit/logFile_test.go @@ -23,21 +23,23 @@ import ( "testing" "time" + "github.com/google/uuid" "k8s.io/minikube/pkg/minikube/localpath" ) func TestLogFile(t *testing.T) { - t.Run("SetLogFile", func(t *testing.T) { + t.Run("OpenAuditLog", func(t *testing.T) { // make sure logs directory exists if err := os.MkdirAll(filepath.Dir(localpath.AuditLog()), 0755); err != nil { t.Fatalf("Error creating logs directory: %v", err) } - if err := setLogFile(); err != nil { - t.Error(err) + if err := openAuditLog(); err != nil { + t.Fatal(err) } }) t.Run("AppendToLog", func(t *testing.T) { + defer closeAuditLog() f, err := os.CreateTemp("", "audit.json") if err != nil { t.Fatalf("Error creating temporary file: %v", err) @@ -48,7 +50,7 @@ func TestLogFile(t *testing.T) { defer func() { currentLogFile = &oldLogFile }() currentLogFile = f - r := newRow("start", "-v", "user1", "v0.17.1", time.Now(), time.Now()) + r := newRow("start", "-v", "user1", "v0.17.1", time.Now(), uuid.New().String()) if err := appendToLog(r); err != nil { t.Fatalf("Error appendingToLog: %v", err) } diff --git a/pkg/minikube/audit/report.go b/pkg/minikube/audit/report.go index 68167571261b..1c255086cb36 100644 --- a/pkg/minikube/audit/report.go +++ b/pkg/minikube/audit/report.go @@ -32,11 +32,10 @@ func Report(lastNLines int) (*RawReport, error) { if lastNLines <= 0 { return nil, fmt.Errorf("last n lines must be 1 or greater") } - if currentLogFile == nil { - if err := setLogFile(); err != nil { - return nil, fmt.Errorf("failed to set the log file: %v", err) - } + if err := openAuditLog(); err != nil { + return nil, err } + defer closeAuditLog() var logs []string s := bufio.NewScanner(currentLogFile) for s.Scan() { diff --git a/pkg/minikube/audit/row.go b/pkg/minikube/audit/row.go index fb5991a0085a..29c5d0b49e6c 100644 --- a/pkg/minikube/audit/row.go +++ b/pkg/minikube/audit/row.go @@ -30,14 +30,20 @@ import ( // row is the log of a single command. type row struct { - args string - command string - endTime string - profile string - startTime string - user string - version string - Data map[string]string `json:"data"` + SpecVersion string `json:"specversion"` + ID string `json:"id"` + Source string `json:"source"` + TypeField string `json:"type"` + DataContentType string `json:"datacontenttype"` + Data map[string]string `json:"data"` + args string + command string + endTime string + id string + profile string + startTime string + user string + version string } // Type returns the cloud events compatible type of this struct. @@ -55,6 +61,7 @@ func (e *row) assignFields() { e.startTime = e.Data["startTime"] e.user = e.Data["user"] e.version = e.Data["version"] + e.id = e.Data["id"] } // toMap combines fields into a string map, @@ -68,11 +75,12 @@ func (e *row) toMap() map[string]string { "startTime": e.startTime, "user": e.user, "version": e.version, + "id": e.id, } } // newRow creates a new audit row. -func newRow(command string, args string, user string, version string, startTime time.Time, endTime time.Time, profile ...string) *row { +func newRow(command string, args string, user string, version string, startTime time.Time, id string, profile ...string) *row { p := viper.GetString(config.ProfileName) if len(profile) > 0 { p = profile[0] @@ -80,11 +88,11 @@ func newRow(command string, args string, user string, version string, startTime return &row{ args: args, command: command, - endTime: endTime.Format(constants.TimeFormat), profile: p, startTime: startTime.Format(constants.TimeFormat), user: user, version: version, + id: id, } } diff --git a/pkg/minikube/audit/row_test.go b/pkg/minikube/audit/row_test.go index 88b54174dfa9..a9512348582e 100644 --- a/pkg/minikube/audit/row_test.go +++ b/pkg/minikube/audit/row_test.go @@ -23,6 +23,7 @@ import ( "testing" "time" + "github.com/google/uuid" "k8s.io/minikube/pkg/minikube/constants" ) @@ -36,8 +37,10 @@ func TestRow(t *testing.T) { stFormatted := st.Format(constants.TimeFormat) et := time.Now() etFormatted := et.Format(constants.TimeFormat) + id := uuid.New().String() - r := newRow(c, a, u, v, st, et, p) + r := newRow(c, a, u, v, st, id, p) + r.endTime = etFormatted t.Run("NewRow", func(t *testing.T) { tests := []struct { @@ -51,7 +54,7 @@ func TestRow(t *testing.T) { {"user", r.user, u}, {"version", r.version, v}, {"startTime", r.startTime, stFormatted}, - {"endTime", r.endTime, etFormatted}, + {"id", r.id, id}, } for _, tt := range tests { @@ -83,7 +86,7 @@ func TestRow(t *testing.T) { {"user", u}, {"version", v}, {"startTime", stFormatted}, - {"endTime", etFormatted}, + {"id", id}, } for _, tt := range tests { @@ -106,7 +109,7 @@ func TestRow(t *testing.T) { }) t.Run("assignFields", func(t *testing.T) { - l := fmt.Sprintf(`{"data":{"args":"%s","command":"%s","endTime":"%s","profile":"%s","startTime":"%s","user":"%s","version":"v0.17.1"},"datacontenttype":"application/json","id":"bc6ec9d4-0d08-4b57-ac3b-db8d67774768","source":"https://minikube.sigs.k8s.io/","specversion":"1.0","type":"io.k8s.sigs.minikube.audit"}`, a, c, etFormatted, p, stFormatted, u) + l := fmt.Sprintf(`{"data":{"args":"%s","command":"%s","id":"%s","profile":"%s","startTime":"%s","user":"%s","version":"v0.17.1"},"datacontenttype":"application/json","id":"bc6ec9d4-0d08-4b57-ac3b-db8d67774768","source":"https://minikube.sigs.k8s.io/","specversion":"1.0","type":"io.k8s.sigs.minikube.audit"}`, a, c, id, p, stFormatted, u) r := &row{} if err := json.Unmarshal([]byte(l), r); err != nil { @@ -126,7 +129,7 @@ func TestRow(t *testing.T) { {"user", r.user, u}, {"version", r.version, v}, {"startTime", r.startTime, stFormatted}, - {"endTime", r.endTime, etFormatted}, + {"id", r.id, id}, } for _, tt := range tests {