From 9fe8946e6610fcd6f7c7bb24c750409024e2d9b6 Mon Sep 17 00:00:00 2001 From: Nikhil Sharma Date: Wed, 11 May 2022 22:38:01 +0530 Subject: [PATCH] Made changes so that we get logs when a command starts no matter that it is finished or not --- cmd/minikube/cmd/root.go | 13 +++-- pkg/minikube/audit/audit.go | 78 +++++++++++++++++++++++++++--- pkg/minikube/audit/audit_test.go | 49 +++++++++++++++++-- pkg/minikube/audit/logFile_test.go | 3 +- pkg/minikube/audit/row.go | 9 ++-- pkg/minikube/audit/row_test.go | 15 +++--- 6 files changed, 145 insertions(+), 22 deletions(-) diff --git a/cmd/minikube/cmd/root.go b/cmd/minikube/cmd/root.go index 870518cddc..6b7b13d082 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 eb4b0ead71..8a41b47ef4 100644 --- a/pkg/minikube/audit/audit.go +++ b/pkg/minikube/audit/audit.go @@ -17,18 +17,25 @@ limitations under the License. package audit import ( + "bufio" + "encoding/json" + "fmt" "os" "os/user" "strings" + "sync" "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/version" ) +var mutex sync.Mutex + // userName pulls the user flag, if empty gets the os username. func userName() string { u := viper.GetString(config.UserFlag) @@ -52,14 +59,73 @@ func args() string { } // Log details about the executed command. -func Log(startTime time.Time) { - if !shouldLog() { - return +func LogCommandStart() (string, error) { + mutex.Lock() + defer mutex.Unlock() + 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 { + mutex.Lock() + defer mutex.Unlock() + if id == "" { + return nil + } + if currentLogFile == nil { + if err := setLogFile(); err != nil { + return fmt.Errorf("failed to set the log file: %v", err) + } + } + _, err := currentLogFile.Seek(0, 0) + if err != nil { + return fmt.Errorf("failed to offset for the next Read or Write on currentLogFile: %v", err) + } + 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) + } + 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) + } + _, err = currentLogFile.Seek(0, 0) + if err != nil { + return fmt.Errorf("failed to offset for the next Read or Write on currentLogFile: %v", err) + } + _, err = currentLogFile.Write([]byte(auditContents)) + if err != nil { + return err + } + return nil } // shouldLog returns if the command should be logged. diff --git a/pkg/minikube/audit/audit_test.go b/pkg/minikube/audit/audit_test.go index e91f7d972a..a79b255603 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("LogCommandEnd", 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_test.go b/pkg/minikube/audit/logFile_test.go index 617a43b8e0..1757df00d0 100644 --- a/pkg/minikube/audit/logFile_test.go +++ b/pkg/minikube/audit/logFile_test.go @@ -23,6 +23,7 @@ import ( "testing" "time" + "github.com/google/uuid" "k8s.io/minikube/pkg/minikube/localpath" ) @@ -48,7 +49,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/row.go b/pkg/minikube/audit/row.go index fb5991a008..94edc406aa 100644 --- a/pkg/minikube/audit/row.go +++ b/pkg/minikube/audit/row.go @@ -37,6 +37,7 @@ type row struct { startTime string user string version string + id string Data map[string]string `json:"data"` } @@ -55,6 +56,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 +70,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,18 +83,18 @@ 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, } } // toFields converts a row to an array of fields, // to be used when converting to a table. func (e *row) toFields() []string { - return []string{e.command, e.args, e.profile, e.user, e.version, e.startTime, e.endTime} + return []string{e.command, e.args, e.profile, e.user, e.version, e.startTime, e.endTime, e.id} } // logsToRows converts audit logs into arrays of rows. diff --git a/pkg/minikube/audit/row_test.go b/pkg/minikube/audit/row_test.go index 88b54174df..8e53e52d45 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 { @@ -97,7 +100,7 @@ func TestRow(t *testing.T) { t.Run("toFields", func(t *testing.T) { got := r.toFields() gotString := strings.Join(got, ",") - want := []string{c, a, p, u, v, stFormatted, etFormatted} + want := []string{c, a, p, u, v, stFormatted, etFormatted, id} wantString := strings.Join(want, ",") if gotString != wantString { @@ -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 {