Skip to content

Commit

Permalink
UPSTREAM: 99237: Use the audit ID of a request for better correlation
Browse files Browse the repository at this point in the history
apiserver: manage audit ID associated with a request
Manage the audit ID early in the request handling logic so that it can
be used by different layers to improve correlation.
- If the caller does not specify a value for Audit-ID in the request
  header, we generate a new audit ID
- If a user specified Audit-ID is too large, we truncate it
- We echo the Audit-ID value to the caller via the response
  Header 'Audit-ID'

apiserver: improve correlation by using the audit ID
- when we forward the request to the aggregated server, set the audit
  ID in the new request header. This allows audit logs from aggregated
  apiservers to be correlated with the kube-apiserver.
- use the audit ID in the current tracer
- use the audit ID in httplog
- when a request panics, log an error with the audit ID.
  • Loading branch information
tkashem committed Apr 14, 2021
1 parent 6870b1a commit 2a98018
Show file tree
Hide file tree
Showing 16 changed files with 442 additions and 63 deletions.
18 changes: 8 additions & 10 deletions staging/src/k8s.io/apiserver/pkg/audit/request.go
Expand Up @@ -23,9 +23,6 @@ import (
"reflect"
"time"

"github.com/google/uuid"
"k8s.io/klog/v2"

authnv1 "k8s.io/api/authentication/v1"
"k8s.io/apimachinery/pkg/api/meta"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
Expand All @@ -36,6 +33,10 @@ import (
auditinternal "k8s.io/apiserver/pkg/apis/audit"
"k8s.io/apiserver/pkg/authentication/user"
"k8s.io/apiserver/pkg/authorization/authorizer"
"k8s.io/apiserver/pkg/endpoints/request"
"k8s.io/klog/v2"

"github.com/google/uuid"
)

const (
Expand All @@ -52,14 +53,11 @@ func NewEventFromRequest(req *http.Request, requestReceivedTimestamp time.Time,
Level: level,
}

// prefer the id from the headers. If not available, create a new one.
// TODO(audit): do we want to forbid the header for non-front-proxy users?
ids := req.Header.Get(auditinternal.HeaderAuditID)
if ids != "" {
ev.AuditID = types.UID(ids)
} else {
ev.AuditID = types.UID(uuid.New().String())
auditID, found := request.AuditIDFrom(req.Context())
if !found {
auditID = types.UID(uuid.New().String())
}
ev.AuditID = auditID

ips := utilnet.SourceIPs(req)
ev.SourceIPs = make([]string, len(ips))
Expand Down
12 changes: 0 additions & 12 deletions staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit.go
Expand Up @@ -195,10 +195,6 @@ type auditResponseWriter struct {
omitStages []auditinternal.Stage
}

func (a *auditResponseWriter) setHttpHeader() {
a.ResponseWriter.Header().Set(auditinternal.HeaderAuditID, string(a.event.AuditID))
}

func (a *auditResponseWriter) processCode(code int) {
a.once.Do(func() {
if a.event.ResponseStatus == nil {
Expand All @@ -216,13 +212,11 @@ func (a *auditResponseWriter) processCode(code int) {
func (a *auditResponseWriter) Write(bs []byte) (int, error) {
// the Go library calls WriteHeader internally if no code was written yet. But this will go unnoticed for us
a.processCode(http.StatusOK)
a.setHttpHeader()
return a.ResponseWriter.Write(bs)
}

func (a *auditResponseWriter) WriteHeader(code int) {
a.processCode(code)
a.setHttpHeader()
a.ResponseWriter.WriteHeader(code)
}

Expand All @@ -245,12 +239,6 @@ func (f *fancyResponseWriterDelegator) Hijack() (net.Conn, *bufio.ReadWriter, er
// fake a response status before protocol switch happens
f.processCode(http.StatusSwitchingProtocols)

// This will be ignored if WriteHeader() function has already been called.
// It's not guaranteed Audit-ID http header is sent for all requests.
// For example, when user run "kubectl exec", apiserver uses a proxy handler
// to deal with the request, users can only get http headers returned by kubelet node.
f.setHttpHeader()

return f.ResponseWriter.(http.Hijacker).Hijack()
}

Expand Down
75 changes: 42 additions & 33 deletions staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit_test.go
Expand Up @@ -673,6 +673,7 @@ func TestAudit(t *testing.T) {
// simplified long-running check
return ri.Verb == "watch"
})
handler = WithAuditID(handler)

req, _ := http.NewRequest(test.verb, test.path, nil)
req = withTestContext(req, &user.DefaultInfo{Name: "admin"}, nil)
Expand Down Expand Up @@ -772,16 +773,20 @@ func TestAuditIDHttpHeader(t *testing.T) {
expectedHeader bool
}{
{
"no http header when there is no audit",
// we always want an audit ID since it can appear in logging/tracing and it is propagated
// to the aggregated apiserver(s) to improve correlation.
"http header when there is no audit",
"",
auditinternal.LevelNone,
false,
true,
},
{
"no http header when there is no audit even the request header specified",
// we always want an audit ID since it can appear in logging/tracing and it is propagated
// to the aggregated apiserver(s) to improve correlation.
"http header when there is no audit even the request header specified",
uuid.New().String(),
auditinternal.LevelNone,
false,
true,
},
{
"server generated header",
Expand All @@ -796,38 +801,42 @@ func TestAuditIDHttpHeader(t *testing.T) {
true,
},
} {
sink := &fakeAuditSink{}
var handler http.Handler
handler = http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
w.WriteHeader(200)
})
policyChecker := policy.FakeChecker(test.level, nil)
handler = WithAudit(handler, sink, policyChecker, nil)

req, _ := http.NewRequest("GET", "/api/v1/namespaces/default/pods", nil)
req.RemoteAddr = "127.0.0.1"
req = withTestContext(req, &user.DefaultInfo{Name: "admin"}, nil)
if test.requestHeader != "" {
req.Header.Add("Audit-ID", test.requestHeader)
}
t.Run(test.desc, func(t *testing.T) {
sink := &fakeAuditSink{}
var handler http.Handler
handler = http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
w.WriteHeader(200)
})
policyChecker := policy.FakeChecker(test.level, nil)

w := httptest.NewRecorder()
handler.ServeHTTP(w, req)
resp := w.Result()
if test.expectedHeader {
if resp.Header.Get("Audit-ID") == "" {
t.Errorf("[%s] expected Audit-ID http header returned, but not returned", test.desc)
continue
}
// if get Audit-ID returned, it should be the same with the requested one
if test.requestHeader != "" && resp.Header.Get("Audit-ID") != test.requestHeader {
t.Errorf("[%s] returned audit http header is not the same with the requested http header, expected: %s, get %s", test.desc, test.requestHeader, resp.Header.Get("Audit-ID"))
handler = WithAudit(handler, sink, policyChecker, nil)
handler = WithAuditID(handler)

req, _ := http.NewRequest("GET", "/api/v1/namespaces/default/pods", nil)
req.RemoteAddr = "127.0.0.1"
req = withTestContext(req, &user.DefaultInfo{Name: "admin"}, nil)
if test.requestHeader != "" {
req.Header.Add("Audit-ID", test.requestHeader)
}
} else {
if resp.Header.Get("Audit-ID") != "" {
t.Errorf("[%s] expected no Audit-ID http header returned, but got %s", test.desc, resp.Header.Get("Audit-ID"))

w := httptest.NewRecorder()
handler.ServeHTTP(w, req)
resp := w.Result()
if test.expectedHeader {
if resp.Header.Get("Audit-ID") == "" {
t.Errorf("[%s] expected Audit-ID http header returned, but not returned", test.desc)
return
}
// if get Audit-ID returned, it should be the same with the requested one
if test.requestHeader != "" && resp.Header.Get("Audit-ID") != test.requestHeader {
t.Errorf("[%s] returned audit http header is not the same with the requested http header, expected: %s, get %s", test.desc, test.requestHeader, resp.Header.Get("Audit-ID"))
}
} else {
if resp.Header.Get("Audit-ID") != "" {
t.Errorf("[%s] expected no Audit-ID http header returned, but got %s", test.desc, resp.Header.Get("Audit-ID"))
}
}
}
})
}
}

Expand Down
68 changes: 68 additions & 0 deletions staging/src/k8s.io/apiserver/pkg/endpoints/filters/with_auditid.go
@@ -0,0 +1,68 @@
/*
Copyright 2021 The Kubernetes Authors.
Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
You may obtain a copy of the License at
http://www.apache.org/licenses/LICENSE-2.0
Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.
*/

package filters

import (
"net/http"

"k8s.io/apimachinery/pkg/types"
auditinternal "k8s.io/apiserver/pkg/apis/audit"
"k8s.io/apiserver/pkg/endpoints/request"

"github.com/google/uuid"
)

// WithAuditID attaches the Audit-ID associated with a request to the context.
//
// a. If the caller does not specify a value for Audit-ID in the request header, we generate a new audit ID
// b. We echo the Audit-ID value to the caller via the response Header 'Audit-ID'.
func WithAuditID(handler http.Handler) http.Handler {
return withAuditID(handler, func() string {
return uuid.New().String()
})
}

func withAuditID(handler http.Handler, newAuditIDFunc func() string) http.Handler {
if newAuditIDFunc == nil {
return handler
}

return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
ctx := r.Context()

auditID := r.Header.Get(auditinternal.HeaderAuditID)
if len(auditID) == 0 {
auditID = newAuditIDFunc()
}

// Note: we save the user specified value of the Audit-ID header as is, no truncation is performed.
r = r.WithContext(request.WithAuditID(ctx, types.UID(auditID)))

// We echo the Audit-ID in to the response header.
// It's not guaranteed Audit-ID http header is sent for all requests.
// For example, when user run "kubectl exec", apiserver uses a proxy handler
// to deal with the request, users can only get http headers returned by kubelet node.
//
// This filter will also be used by other aggregated api server(s). For an aggregated API
// we don't want to see the same audit ID appearing more than once.
if value := w.Header().Get(auditinternal.HeaderAuditID); len(value) == 0 {
w.Header().Set(auditinternal.HeaderAuditID, auditID)
}

handler.ServeHTTP(w, r)
})
}
@@ -0,0 +1,113 @@
/*
Copyright 2021 The Kubernetes Authors.
Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
You may obtain a copy of the License at
http://www.apache.org/licenses/LICENSE-2.0
Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.
*/

package filters

import (
"fmt"
"net/http"
"net/http/httptest"
"testing"

"github.com/google/uuid"
"k8s.io/apiserver/pkg/endpoints/request"
)

func TestWithAuditID(t *testing.T) {
largeAuditID := fmt.Sprintf("%s-%s", uuid.New().String(), uuid.New().String())
tests := []struct {
name string
newAuditIDFunc func() string
auditIDSpecified string
auditIDExpected string
}{
{
name: "user specifies a value for Audit-ID in the request header",
auditIDSpecified: "foo-bar-baz",
auditIDExpected: "foo-bar-baz",
},
{
name: "user does not specify a value for Audit-ID in the request header",
newAuditIDFunc: func() string {
return "foo-bar-baz"
},
auditIDExpected: "foo-bar-baz",
},
{
name: "the value in Audit-ID request header is too large, should not be truncated",
auditIDSpecified: largeAuditID,
auditIDExpected: largeAuditID,
},
{
name: "the generated Audit-ID is too large, should not be truncated",
newAuditIDFunc: func() string {
return largeAuditID
},
auditIDExpected: largeAuditID,
},
}

for _, test := range tests {
t.Run(test.name, func(t *testing.T) {
const auditKey = "Audit-ID"
var (
innerHandlerCallCount int
auditIDGot string
found bool
)
handler := http.HandlerFunc(func(_ http.ResponseWriter, req *http.Request) {
innerHandlerCallCount++

// does the inner handler see the audit ID?
v, ok := request.AuditIDFrom(req.Context())

found = ok
auditIDGot = string(v)
})

wrapped := WithAuditID(handler)
if test.newAuditIDFunc != nil {
wrapped = withAuditID(handler, test.newAuditIDFunc)
}

testRequest, err := http.NewRequest(http.MethodGet, "/api/v1/namespaces", nil)
if err != nil {
t.Fatalf("failed to create new http request - %v", err)
}
if len(test.auditIDSpecified) > 0 {
testRequest.Header.Set(auditKey, test.auditIDSpecified)
}

w := httptest.NewRecorder()
wrapped.ServeHTTP(w, testRequest)

if innerHandlerCallCount != 1 {
t.Errorf("WithAuditID: expected the inner handler to be invoked once, but was invoked %d times", innerHandlerCallCount)
}
if !found {
t.Error("WithAuditID: expected request.AuditIDFrom to return true, but got false")
}
if test.auditIDExpected != auditIDGot {
t.Errorf("WithAuditID: expected the request context to have: %q, but got=%q", test.auditIDExpected, auditIDGot)
}

auditIDEchoed := w.Header().Get(auditKey)
if test.auditIDExpected != auditIDEchoed {
t.Errorf("WithAuditID: expected Audit-ID response header: %q, but got: %q", test.auditIDExpected, auditIDEchoed)
}
})
}
}
15 changes: 15 additions & 0 deletions staging/src/k8s.io/apiserver/pkg/endpoints/handlers/helpers.go
Expand Up @@ -20,6 +20,7 @@ import (
"net/http"

utilnet "k8s.io/apimachinery/pkg/util/net"
"k8s.io/apiserver/pkg/endpoints/request"
)

const (
Expand Down Expand Up @@ -73,3 +74,17 @@ func (lazy *lazyAccept) String() string {

return "unknown"
}

// lazyAuditID implements Stringer interface to lazily retrieve
// the audit ID associated with the request.
type lazyAuditID struct {
req *http.Request
}

func (lazy *lazyAuditID) String() string {
if lazy.req != nil {
return request.GetAuditIDTruncated(lazy.req)
}

return "unknown"
}
Expand Up @@ -26,6 +26,7 @@ func traceFields(req *http.Request) []utiltrace.Field {
return []utiltrace.Field{
{Key: "url", Value: req.URL.Path},
{Key: "user-agent", Value: &lazyTruncatedUserAgent{req: req}},
{Key: "audit-id", Value: &lazyAuditID{req: req}},
{Key: "client", Value: &lazyClientIP{req: req}},
{Key: "accept", Value: &lazyAccept{req: req}},
{Key: "protocol", Value: req.Proto}}
Expand Down

0 comments on commit 2a98018

Please sign in to comment.