Write commands to audit log regardless of whether it terminates cleanly

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

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 {

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

pkg/minikube/audit/logFile.go

@@ -20,36 +20,43 @@ import (
 	"fmt"
 	"os"
 
+	"k8s.io/klog/v2"
 	"k8s.io/minikube/pkg/minikube/localpath"
 	"k8s.io/minikube/pkg/minikube/out/register"
 )
 
 // 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)
 	}

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

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() {

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,23 +75,24 @@ 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]
 	}
 	return &row{
 		args:      args,
 		command:   command,
-		endTime:   endTime.Format(constants.TimeFormat),
 		profile:   p,
 		startTime: startTime.Format(constants.TimeFormat),
 		user:      user,
 		version:   version,
+		id:        id,
 	}
 }