Merge pull request #13307 from NikhilSharmaWe/auditLog

Write commands to audit log regardless of whether it terminates cleanly
pull/14352/head
Steven Powell 2022-06-17 09:57:44 -07:00 committed by GitHub
commit 8dac72ba40
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
8 changed files with 171 additions and 44 deletions

View File

@ -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

View File

@ -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 {

View File

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

View File

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

View File

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

View File

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

View File

@ -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,
}
}

View File

@ -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 {