Merge pull request #14596 from spowelljr/optimizeAudit

Optimize audit logging

Author: spowelljr

pkg/minikube/audit/audit.go

@@ -90,7 +90,13 @@ func LogCommandEnd(id string) error {
 	if err != nil {
 		return fmt.Errorf("failed to convert logs to rows: %v", err)
 	}
-	auditContents := ""
+	// 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
+	}
 	var entriesNeedsToUpdate int
 	for _, v := range rowSlice {
 		if v.id == id {
@@ -102,21 +108,13 @@ func LogCommandEnd(id string) error {
 		if err != nil {
 			return err
 		}
-		auditContents += string(auditLog) + "\n"
+		if _, err = currentLogFile.WriteString(string(auditLog) + "\n"); err != nil {
+			return fmt.Errorf("failed to write to audit log: %v", err)
+		}
 	}
 	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
 }
 

pkg/minikube/audit/logFile.go

@@ -30,6 +30,10 @@ var currentLogFile *os.File
 
 // openAuditLog opens the audit log file or creates it if it doesn't exist.
 func openAuditLog() error {
+	// this is so we can manually set the log file for tests
+	if currentLogFile != nil {
+		return nil
+	}
 	lp := localpath.AuditLog()
 	f, err := os.OpenFile(lp, os.O_APPEND|os.O_CREATE|os.O_RDWR, 0644)
 	if err != nil {
@@ -44,6 +48,7 @@ func closeAuditLog() {
 	if err := currentLogFile.Close(); err != nil {
 		klog.Errorf("failed to close the audit log: %v", err)
 	}
+	currentLogFile = nil
 }
 
 // appendToLog appends the row to the log file.

pkg/minikube/audit/logFile_test.go

@@ -36,27 +36,30 @@ func TestLogFile(t *testing.T) {
 		if err := openAuditLog(); err != nil {
 			t.Fatal(err)
 		}
+		closeAuditLog()
 	})
 
 	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)
 		}
 		defer os.Remove(f.Name())
 
-		oldLogFile := *currentLogFile
-		defer func() { currentLogFile = &oldLogFile }()
 		currentLogFile = f
+		defer closeAuditLog()
 
 		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)
 		}
 
+		currentLogFile, err = os.Open(f.Name())
+		if err != nil {
+			t.Fatal(err)
+		}
 		b := make([]byte, 100)
-		if _, err := f.Read(b); err != nil && err != io.EOF {
+		if _, err := currentLogFile.Read(b); err != nil && err != io.EOF {
 			t.Errorf("Log was not appended to file: %v", err)
 		}
 	})

pkg/minikube/audit/report_test.go

@@ -17,6 +17,7 @@ limitations under the License.
 package audit
 
 import (
+	"io"
 	"os"
 	"testing"
 )
@@ -30,18 +31,18 @@ func TestReport(t *testing.T) {
 
 	s := `{"data":{"args":"-p mini1","command":"start","endTime":"Wed, 03 Feb 2021 15:33:05 MST","profile":"mini1","startTime":"Wed, 03 Feb 2021 15:30:33 MST","user":"user1"},"datacontenttype":"application/json","id":"9b7593cb-fbec-49e5-a3ce-bdc2d0bfb208","source":"https://minikube.sigs.k8s.io/","specversion":"1.0","type":"io.k8s.si  gs.minikube.audit"}
 {"data":{"args":"-p mini1","command":"start","endTime":"Wed, 03 Feb 2021 15:33:05 MST","profile":"mini1","startTime":"Wed, 03 Feb 2021 15:30:33 MST","user":"user1"},"datacontenttype":"application/json","id":"9b7593cb-fbec-49e5-a3ce-bdc2d0bfb208","source":"https://minikube.sigs.k8s.io/","specversion":"1.0","type":"io.k8s.si  gs.minikube.audit"}
-{"data":{"args":"--user user2","command":"logs","endTime":"Tue, 02 Feb 2021 16:46:20 MST","profile":"minikube","startTime":"Tue, 02 Feb 2021 16:46:00 MST","user":"user2"},"datacontenttype":"application/json","id":"fec03227-2484-48b6-880a-88fd010b5efd","source":"https://minikube.sigs.k8s.io/","specversion":"1.0","type":"io.k8s.sigs.minikube.audit"}`
+{"data":{"args":"--user user2","command":"logs","endTime":"Tue, 02 Feb 2021 16:46:20 MST","profile":"minikube","startTime":"Tue, 02 Feb 2021 16:46:00 MST","user":"user2"},"datacontenttype":"application/json","id":"fec03227-2484-48b6-880a-88fd010b5efd","source":"https://minikube.sigs.k8s.io/","specversion":"1.0","type":"io.k8s.sigs.minikube.audit"}
+`
 
 	if _, err := f.WriteString(s); err != nil {
 		t.Fatalf("failed writing to file: %v", err)
 	}
-	if _, err := f.Seek(0, 0); err != nil {
+	if _, err := f.Seek(0, io.SeekStart); err != nil {
 		t.Fatalf("failed seeking to start of file: %v", err)
 	}
 
-	oldLogFile := *currentLogFile
-	defer func() { currentLogFile = &oldLogFile }()
 	currentLogFile = f
+	defer closeAuditLog()
 
 	wantedLines := 2
 	r, err := Report(wantedLines)