Made changes so that we get logs when a command starts no matter that it is finished or not

Author: NikhilSharmaWe

cmd/minikube/cmd/root.go

@@ -23,7 +23,6 @@ import (
 	"path/filepath"
 	"runtime"
 	"strings"
-	"time"
 
 	"github.com/spf13/cobra"
 	"github.com/spf13/pflag"
@@ -78,8 +77,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("%v", err)
+	}
+	defer func(){
+		err := audit.LogCommandEnd(auditID)
+		if err != nil{
+			klog.Errorf("%v", err)
+		}
+	}()
 	// Check whether this is a windows binary (.exe) running inisde WSL.
 	if runtime.GOOS == "windows" && detect.IsMicrosoftWSL() {
 		var found = false

pkg/minikube/audit/audit.go

@@ -17,14 +17,17 @@ limitations under the License.
 package audit
 
 import (
+	"encoding/json"
+	"fmt"
 	"os"
 	"os/user"
 	"strings"
 	"time"
 
+	"github.com/google/uuid"
 	"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"
 )
 
@@ -51,14 +54,40 @@ func args() string {
 }
 
 // Log details about the executed command.
-func Log(startTime time.Time) {
+func LogCommandStart() (string, error) {
 	if len(os.Args) < 2 || !shouldLog() {
-		return
+		return "", fmt.Errorf("This command should not be logged and len(os.Args) : %v, should be less than 2", len(os.Args))
 	}
-	r := newRow(os.Args[1], args(), userName(), version.GetVersion(), startTime, time.Now())
+	id := uuid.New().String()
+	r := newRow(os.Args[1], args(), userName(), version.GetVersion(), time.Now(), id)
 	if err := appendToLog(r); err != nil {
-		klog.Warning(err)
+		return "", fmt.Errorf("%v", err)
 	}
+	return r.id, nil
+}
+
+func LogCommandEnd(id string) error {
+	if currentLogFile == nil {
+		if err := setLogFile(); err != nil {
+			return fmt.Errorf("failed to set the log file: %v", err)
+		}
+	}
+	var auditLogs []byte
+	_, err := currentLogFile.Read(auditLogs)
+	if err != nil {
+		return fmt.Errorf("%v", err)
+	}
+	var rowSlice []row
+	err = json.Unmarshal(auditLogs, &rowSlice)
+	if err != nil {
+		return fmt.Errorf("%v", err)
+	}
+	for _, v := range rowSlice {
+		if v.id == id {
+			v.endTime = time.Now().Format(constants.TimeFormat)
+		}
+	}
+	return nil
 }
 
 // shouldLog returns if the command should be logged.

pkg/minikube/audit/audit_test.go

@@ -20,8 +20,8 @@ import (
 	"os"
 	"os/user"
 	"testing"
-	"time"
 
+	"github.com/google/uuid"
 	"github.com/spf13/viper"
 	"k8s.io/minikube/pkg/minikube/config"
 )
@@ -170,11 +170,25 @@ 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"}
 
-		Log(time.Now())
+		_, err := LogCommandStart()
+		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"}
+
+		err := LogCommandEnd(uuid.New().String())
+		if err != nil {
+			t.Fatal(err)
+		}
 	})
 }

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)
 		}

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"`
 }
 
@@ -72,19 +73,19 @@ func (e *row) toMap() map[string]string {
 }
 
 // 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]
 	}
 	return &row{
 		args:      args,
 		command:   command,
-		endTime:   endTime.Format(constants.TimeFormat),
 		profile:   p,
 		startTime: startTime.Format(constants.TimeFormat),
 		user:      user,
 		version:   version,
+		id:        id,
 	}
 }
 

pkg/minikube/audit/row_test.go

@@ -23,6 +23,7 @@ import (
 	"testing"
 	"time"
 
+	"github.com/google/uuid"
 	"k8s.io/minikube/pkg/minikube/constants"
 )
 
@@ -34,10 +35,9 @@ func TestRow(t *testing.T) {
 	v := "v0.17.1"
 	st := time.Now()
 	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)
 
 	t.Run("NewRow", func(t *testing.T) {
 		tests := []struct {
@@ -51,7 +51,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 +83,7 @@ func TestRow(t *testing.T) {
 			{"user", u},
 			{"version", v},
 			{"startTime", stFormatted},
-			{"endTime", etFormatted},
+			{"id", id},
 		}
 
 		for _, tt := range tests {
@@ -97,7 +97,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, id}
 		wantString := strings.Join(want, ",")
 
 		if gotString != wantString {
@@ -106,7 +106,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 +126,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 {