diff --git a/pkg/endpoints/audit_test.go b/pkg/endpoints/audit_test.go index 4fd42e61a..728e93b2a 100644 --- a/pkg/endpoints/audit_test.go +++ b/pkg/endpoints/audit_test.go @@ -127,7 +127,7 @@ func TestAudit(t *testing.T) { }, selfLinker, 200, - 1, + 2, []eventCheck{ noRequestBody(0), responseBodyMatches(0, `{.*"name":"c".*}`), @@ -144,7 +144,7 @@ func TestAudit(t *testing.T) { namespace: "other", }, 200, - 1, + 2, []eventCheck{ noRequestBody(0), responseBodyMatches(0, `{.*"name":"a".*"name":"b".*}`), @@ -157,7 +157,7 @@ func TestAudit(t *testing.T) { }, selfLinker, 201, - 1, + 2, []eventCheck{ requestBodyIs(0, string(simpleFooJSON)), responseBodyMatches(0, `{.*"foo".*}`), @@ -170,7 +170,7 @@ func TestAudit(t *testing.T) { }, selfLinker, 405, - 1, + 2, []eventCheck{ noRequestBody(0), // the 405 is thrown long before the create handler would be executed noResponseBody(0), // the 405 is thrown long before the create handler would be executed @@ -183,7 +183,7 @@ func TestAudit(t *testing.T) { }, selfLinker, 200, - 1, + 2, []eventCheck{ noRequestBody(0), responseBodyMatches(0, `{.*"kind":"Status".*"status":"Success".*}`), @@ -196,7 +196,7 @@ func TestAudit(t *testing.T) { }, selfLinker, 200, - 1, + 2, []eventCheck{ requestBodyMatches(0, "DeleteOptions"), responseBodyMatches(0, `{.*"kind":"Status".*"status":"Success".*}`), @@ -209,7 +209,7 @@ func TestAudit(t *testing.T) { }, selfLinker, 200, - 1, + 2, []eventCheck{ requestBodyIs(0, string(simpleCPrimeJSON)), responseBodyMatches(0, `{.*"bla".*}`), @@ -222,7 +222,7 @@ func TestAudit(t *testing.T) { }, selfLinker, 400, - 1, + 2, []eventCheck{ requestBodyIs(0, string(simpleCPrimeJSON)), responseBodyMatches(0, `"Status".*"status":"Failure".*"code":400}`), @@ -242,7 +242,7 @@ func TestAudit(t *testing.T) { namespace: "other", }, 200, - 1, + 2, []eventCheck{ requestBodyIs(0, `{"labels":{"foo":"bar"}}`), responseBodyMatches(0, `"name":"c".*"labels":{"foo":"bar"}`), @@ -259,7 +259,7 @@ func TestAudit(t *testing.T) { namespace: "other", }, 200, - 2, + 3, []eventCheck{ noRequestBody(0), noResponseBody(0), diff --git a/pkg/endpoints/filters/audit.go b/pkg/endpoints/filters/audit.go index df333253d..02b32a007 100644 --- a/pkg/endpoints/filters/audit.go +++ b/pkg/endpoints/filters/audit.go @@ -92,11 +92,10 @@ func WithAudit(handler http.Handler, requestContextMapper request.RequestContext sink.ProcessEvents(ev) // intercept the status code - longRunning := false var longRunningSink audit.Sink if longRunningCheck != nil { ri, _ := request.RequestInfoFrom(ctx) - if longRunning = longRunningCheck(req, ri); longRunning { + if longRunningCheck(req, ri) { longRunningSink = sink } } @@ -106,20 +105,34 @@ func WithAudit(handler http.Handler, requestContextMapper request.RequestContext // running requests, this will be the second audit event. defer func() { if r := recover(); r != nil { + defer panic(r) + ev.Stage = auditinternal.StagePanic ev.ResponseStatus = &metav1.Status{ - Code: http.StatusInternalServerError, + Code: http.StatusInternalServerError, + Status: metav1.StatusFailure, + Reason: metav1.StatusReasonInternalError, + Message: fmt.Sprintf("APIServer panic'd: %v", r), } sink.ProcessEvents(ev) - panic(r) + return } - if ev.ResponseStatus == nil { - ev.ResponseStatus = &metav1.Status{ - Code: 200, - } + // if no StageResponseStarted event was sent b/c neither a status code nor a body was sent, fake it here + fakedSuccessStatus := &metav1.Status{ + Code: http.StatusOK, + Status: metav1.StatusSuccess, + Message: "Connection closed early", + } + if ev.ResponseStatus == nil && longRunningSink != nil { + ev.ResponseStatus = fakedSuccessStatus + ev.Stage = auditinternal.StageResponseStarted + longRunningSink.ProcessEvents(ev) } ev.Stage = auditinternal.StageResponseComplete + if ev.ResponseStatus == nil { + ev.ResponseStatus = fakedSuccessStatus + } sink.ProcessEvents(ev) }() handler.ServeHTTP(respWriter, req) diff --git a/pkg/endpoints/filters/audit_test.go b/pkg/endpoints/filters/audit_test.go index b4fb7175e..b85f6c8c2 100644 --- a/pkg/endpoints/filters/audit_test.go +++ b/pkg/endpoints/filters/audit_test.go @@ -19,6 +19,7 @@ package filters import ( "bufio" "bytes" + "fmt" "net" "net/http" "net/http/httptest" @@ -177,10 +178,17 @@ func (*fakeHTTPHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) { } func TestAudit(t *testing.T) { - shortRunningPrefix := `[\d\:\-\.\+TZ]+ AUDIT: id="[\w-]+" ip="127.0.0.1" method="list" user="admin" groups="" as="" asgroups="" namespace="default" uri="/api/v1/namespaces/default/pods"` - longRunningPrefix := `[\d\:\-\.\+TZ]+ AUDIT: id="[\w-]+" ip="127.0.0.1" method="watch" user="admin" groups="" as="" asgroups="" namespace="default" uri="/api/v1/namespaces/default/pods\?watch=true"` + writingShortRunningPrefix := func(stage string) string { + return fmt.Sprintf(`[\d\:\-\.\+TZ]+ AUDIT: id="[\w-]+" stage="%s" ip="127.0.0.1" method="update" user="admin" groups="" as="" asgroups="" namespace="default" uri="/api/v1/namespaces/default/pods/foo"`, stage) + } + readOnlyShortRunningPrefix := func(stage string) string { + return fmt.Sprintf(`[\d\:\-\.\+TZ]+ AUDIT: id="[\w-]+" stage="%s" ip="127.0.0.1" method="get" user="admin" groups="" as="" asgroups="" namespace="default" uri="/api/v1/namespaces/default/pods/foo"`, stage) + } + longRunningPrefix := func(stage string) string { + return fmt.Sprintf(`[\d\:\-\.\+TZ]+ AUDIT: id="[\w-]+" stage="%s" ip="127.0.0.1" method="watch" user="admin" groups="" as="" asgroups="" namespace="default" uri="/api/v1/namespaces/default/pods\?watch=true"`, stage) + } - shortRunningPath := "/api/v1/namespaces/default/pods" + shortRunningPath := "/api/v1/namespaces/default/pods/foo" longRunningPath := "/api/v1/namespaces/default/pods?watch=true" delay := 500 * time.Millisecond @@ -188,58 +196,93 @@ func TestAudit(t *testing.T) { for _, test := range []struct { desc string path string + verb string handler func(http.ResponseWriter, *http.Request) expected []string }{ - // short running requests + // short running requests with read-only verb { - "empty", + "read-only empty", shortRunningPath, + "GET", func(http.ResponseWriter, *http.Request) {}, []string{ - shortRunningPrefix + ` response="200"`, + readOnlyShortRunningPrefix(auditinternal.StageRequestReceived) + ` response=""`, + readOnlyShortRunningPrefix(auditinternal.StageResponseComplete) + ` response="200"`, }, }, { - "sleep", + "read-only panic", shortRunningPath, + "GET", + func(w http.ResponseWriter, req *http.Request) { + panic("kaboom") + }, + []string{ + readOnlyShortRunningPrefix(auditinternal.StageRequestReceived) + ` response=""`, + readOnlyShortRunningPrefix(auditinternal.StagePanic) + ` response="500"`, + }, + }, + + // short running request with non-read-only verb + { + "writing empty", + shortRunningPath, + "PUT", + func(http.ResponseWriter, *http.Request) {}, + []string{ + writingShortRunningPrefix(auditinternal.StageRequestReceived) + ` response=""`, + writingShortRunningPrefix(auditinternal.StageResponseComplete) + ` response="200"`, + }, + }, + { + "writing sleep", + shortRunningPath, + "PUT", func(http.ResponseWriter, *http.Request) { time.Sleep(delay) }, []string{ - shortRunningPrefix + ` response="200"`, + writingShortRunningPrefix(auditinternal.StageRequestReceived) + ` response=""`, + writingShortRunningPrefix(auditinternal.StageResponseComplete) + ` response="200"`, }, }, { - "403+write", + "writing 403+write", shortRunningPath, + "PUT", func(w http.ResponseWriter, req *http.Request) { w.WriteHeader(403) w.Write([]byte("foo")) }, []string{ - shortRunningPrefix + ` response="403"`, + writingShortRunningPrefix(auditinternal.StageRequestReceived) + ` response=""`, + writingShortRunningPrefix(auditinternal.StageResponseComplete) + ` response="403"`, }, }, { - "panic", + "writing panic", shortRunningPath, + "PUT", func(w http.ResponseWriter, req *http.Request) { panic("kaboom") }, []string{ - shortRunningPrefix + ` response="500"`, + writingShortRunningPrefix(auditinternal.StageRequestReceived) + ` response=""`, + writingShortRunningPrefix(auditinternal.StagePanic) + ` response="500"`, }, }, { - "write+panic", + "writing write+panic", shortRunningPath, + "PUT", func(w http.ResponseWriter, req *http.Request) { w.Write([]byte("foo")) panic("kaboom") }, []string{ - shortRunningPrefix + ` response="500"`, + writingShortRunningPrefix(auditinternal.StageRequestReceived) + ` response=""`, + writingShortRunningPrefix(auditinternal.StagePanic) + ` response="500"`, }, }, @@ -247,76 +290,92 @@ func TestAudit(t *testing.T) { { "empty longrunning", longRunningPath, + "GET", func(http.ResponseWriter, *http.Request) {}, []string{ - longRunningPrefix + ` response="200"`, + longRunningPrefix(auditinternal.StageRequestReceived) + ` response=""`, + longRunningPrefix(auditinternal.StageResponseStarted) + ` response="200"`, + longRunningPrefix(auditinternal.StageResponseComplete) + ` response="200"`, }, }, { "sleep longrunning", longRunningPath, + "GET", func(http.ResponseWriter, *http.Request) { time.Sleep(delay) }, []string{ - longRunningPrefix + ` response="200"`, + longRunningPrefix(auditinternal.StageRequestReceived) + ` response=""`, + longRunningPrefix(auditinternal.StageResponseStarted) + ` response="200"`, + longRunningPrefix(auditinternal.StageResponseComplete) + ` response="200"`, }, }, { "sleep+403 longrunning", longRunningPath, + "GET", func(w http.ResponseWriter, req *http.Request) { time.Sleep(delay) w.WriteHeader(403) }, []string{ - longRunningPrefix + ` response=""`, - longRunningPrefix + ` response="403"`, + longRunningPrefix(auditinternal.StageRequestReceived) + ` response=""`, + longRunningPrefix(auditinternal.StageResponseStarted) + ` response="403"`, + longRunningPrefix(auditinternal.StageResponseComplete) + ` response="403"`, }, }, { "write longrunning", longRunningPath, + "GET", func(w http.ResponseWriter, req *http.Request) { w.Write([]byte("foo")) }, []string{ - longRunningPrefix + ` response=""`, - longRunningPrefix + ` response="200"`, + longRunningPrefix(auditinternal.StageRequestReceived) + ` response=""`, + longRunningPrefix(auditinternal.StageResponseStarted) + ` response="200"`, + longRunningPrefix(auditinternal.StageResponseComplete) + ` response="200"`, }, }, { "403+write longrunning", longRunningPath, + "GET", func(w http.ResponseWriter, req *http.Request) { w.WriteHeader(403) w.Write([]byte("foo")) }, []string{ - longRunningPrefix + ` response=""`, - longRunningPrefix + ` response="403"`, + longRunningPrefix(auditinternal.StageRequestReceived) + ` response=""`, + longRunningPrefix(auditinternal.StageResponseStarted) + ` response="403"`, + longRunningPrefix(auditinternal.StageResponseComplete) + ` response="403"`, }, }, { "panic longrunning", longRunningPath, + "GET", func(w http.ResponseWriter, req *http.Request) { panic("kaboom") }, []string{ - longRunningPrefix + ` response="500"`, + longRunningPrefix(auditinternal.StageRequestReceived) + ` response=""`, + longRunningPrefix(auditinternal.StagePanic) + ` response="500"`, }, }, { "write+panic longrunning", longRunningPath, + "GET", func(w http.ResponseWriter, req *http.Request) { w.Write([]byte("foo")) panic("kaboom") }, []string{ - longRunningPrefix + ` response=""`, - longRunningPrefix + ` response="500"`, + longRunningPrefix(auditinternal.StageRequestReceived) + ` response=""`, + longRunningPrefix(auditinternal.StageResponseStarted) + ` response="200"`, + longRunningPrefix(auditinternal.StagePanic) + ` response="500"`, }, }, } { @@ -330,7 +389,7 @@ func TestAudit(t *testing.T) { return ri.Verb == "watch" }) - req, _ := http.NewRequest("GET", test.path, nil) + req, _ := http.NewRequest(test.verb, test.path, nil) req.RemoteAddr = "127.0.0.1" func() { diff --git a/plugin/pkg/audit/log/backend.go b/plugin/pkg/audit/log/backend.go index fe15a77d8..3712d728c 100644 --- a/plugin/pkg/audit/log/backend.go +++ b/plugin/pkg/audit/log/backend.go @@ -82,8 +82,8 @@ func (b *backend) logEvent(ev *auditinternal.Event) { ip = ev.SourceIPs[0] } - line := fmt.Sprintf("%s AUDIT: id=%q ip=%q method=%q user=%q groups=%q as=%q asgroups=%q namespace=%q uri=%q response=\"%s\"\n", - ev.Timestamp.Format(time.RFC3339Nano), ev.AuditID, ip, ev.Verb, username, groups, asuser, asgroups, namespace, ev.RequestURI, response) + line := fmt.Sprintf("%s AUDIT: id=%q stage=%q ip=%q method=%q user=%q groups=%q as=%q asgroups=%q namespace=%q uri=%q response=\"%s\"\n", + ev.Timestamp.Format(time.RFC3339Nano), ev.AuditID, ev.Stage, ip, ev.Verb, username, groups, asuser, asgroups, namespace, ev.RequestURI, response) if _, err := fmt.Fprint(b.out, line); err != nil { glog.Errorf("Unable to write audit log: %s, the error is: %v", line, err) }