Repository: kubernetes/minikube (go)

Issue:
Audit log defer not always being called
When any minikube command is run we have a [defer statement](https://github.com/kubernetes/minikube/blob/master/cmd/minikube/cmd/root.go#L81) that logs the command to the audit log. However, on `minikube start` sometimes we terminate the execution in a way that the defer is not run and then the start command is not added to the audit log.

I have a proposed way to remedy this, the only reason we defer it is so we can add then end time to the audit log, but to prevent the defer issue we can log everything but the end time to the audit log, and then if the command completes we can add the end time to the audit entry.

The one case we have to watch out for is if the user starts two `minikube start` commands at the same time, we simply can't modify the last entry in the log, so we'll need to make sure to track the index of the entry in the audit log.

Example:
```
# 1st minikube start
$ minikube start -p p1

# Audit log
minikube start -p p1 started at 1:00

# 2nd minikube start
$ minikube start -p p2

# Audit log
minikube start -p p1 started at 1:00
minikube start -p p2 started at 1:01

# 1st minikube start finishs

# Need to make sure we update the second last entry
minikube start -p p1 started at 1:00 ended at 1:03
minikube start -p p2 started at 1:01
```

Pull request:
Write commands to audit log regardless of whether it terminates cleanly

<!-- 🎉 Thank you for contributing to minikube! 🎉 Here are some hints to get your PR merged faster:

1. Your PR title will be included in the release notes, choose it carefully
2. If the PR fixes an issue, add "fixes #<issue number>" to the description.
3. If the PR is a user interface change, please include a "before" and "after" example.
4. If the PR is a large design change, please include an enhancement proposal:
https://github.com/kubernetes/minikube/tree/master/enhancements
-->
Fixes #13186

**Before (note start entry is not present):**
```
$ minikube delete
🙄  "minikube" profile does not exist, trying anyways.
💀  Removed all traces of the "minikube" cluster.
$ minikube delete
🙄  "minikube" profile does not exist, trying anyways.
💀  Removed all traces of the "minikube" cluster.
$ minikube start --driver docker
😄  minikube v1.26.0-beta.1 on Darwin 12.4
✨  Using the docker driver based on user configuration

💣  Exiting due to PROVIDER_DOCKER_NOT_RUNNING: "docker version --format -" exit status 1: Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?
💡  Suggestion: Start the Docker service
📘  Documentation: https://minikube.sigs.k8s.io/docs/drivers/docker/

$ minikube logs --audit

==> Audit <==
|---------|------|----------|--------------|----------------|---------------------|---------------------|
| Command | Args | Profile  |     User     |    Version     |     Start Time      |      End Time       |
|---------|------|----------|--------------|----------------|---------------------|---------------------|
| delete  |      | minikube | powellsteven | v1.26.0-beta.1 | 14 Jun 22 15:44 PDT | 14 Jun 22 15:44 PDT |
| delete  |      | minikube | powellsteven | v1.26.0-beta.1 | 14 Jun 22 15:44 PDT | 14 Jun 22 15:44 PDT |
|---------|------|----------|--------------|----------------|---------------------|---------------------|
```

**After (note start entry is present):**
```
$ minikube delete
🙄  "minikube" profile does not exist, trying anyways.
💀  Removed all traces of the "minikube" cluster.
$ minikube delete
🙄  "minikube" profile does not exist, trying anyways.
💀  Removed all traces of the "minikube" cluster.
$ minikube start --driver docker
😄  minikube v1.26.0-beta.1 on Darwin 12.4
✨  Using the docker driver based on user configuration

💣  Exiting due to PROVIDER_DOCKER_NOT_RUNNING: "docker version --format -" exit status 1: Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?
💡  Suggestion: Start the Docker service
📘  Documentation: https://minikube.sigs.k8s.io/docs/drivers/docker/

$ minikube logs --audit

==> Audit <==
|---------|-----------------|----------|--------------|----------------|---------------------|---------------------|
| Command |      Args       | Profile  |     User     |    Version     |     Start Time      |      End Time       |
|---------|-----------------|----------|--------------|----------------|---------------------|---------------------|
| delete  |                 | minikube | powellsteven | v1.26.0-beta.1 | 14 Jun 22 15:42 PDT | 14 Jun 22 15:42 PDT |
| delete  |                 | minikube | powellsteven | v1.26.0-beta.1 | 14 Jun 22 15:42 PDT | 14 Jun 22 15:42 PDT |
| start   | --driver docker | minikube | powellsteven | v1.26.0-beta.1 | 14 Jun 22 15:42 PDT |                     |
|---------|-----------------|----------|--------------|----------------|---------------------|---------------------|
```

Patch:
diff --git a/cmd/minikube/cmd/root.go b/cmd/minikube/cmd/root.go
index 870518cdd..6b7b13d08 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 eb4b0ead7..e119429da 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/logFile.go b/pkg/minikube/audit/logFile.go
index 1762070f1..437114aa8 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/report.go b/pkg/minikube/audit/report.go
index 681675712..1c255086c 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 fb5991a00..29c5d0b49 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,
 	}
 }
 


Test patch:
diff --git a/pkg/minikube/audit/audit_test.go b/pkg/minikube/audit/audit_test.go
index e91f7d972..262ceac82 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_test.go b/pkg/minikube/audit/logFile_test.go
index 617a43b8e..916791108 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/row_test.go b/pkg/minikube/audit/row_test.go
index 88b54174d..a95123485 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 {