From 31653bacb9b979ee2f878ebece7e25f79d3f9aa6 Mon Sep 17 00:00:00 2001 From: Abu Kashem Date: Tue, 2 Mar 2021 19:22:39 -0500 Subject: [PATCH 1/2] 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' --- .../src/k8s.io/apiserver/pkg/audit/request.go | 18 ++- .../apiserver/pkg/endpoints/filters/audit.go | 12 -- .../pkg/endpoints/filters/audit_test.go | 79 ++++++------ .../pkg/endpoints/filters/with_auditid.go | 68 +++++++++++ .../endpoints/filters/with_auditid_test.go | 113 ++++++++++++++++++ .../pkg/endpoints/request/auditid.go | 66 ++++++++++ .../pkg/endpoints/request/auditid_test.go | 68 +++++++++++ .../src/k8s.io/apiserver/pkg/server/config.go | 1 + .../filters/priority-and-fairness_test.go | 1 + 9 files changed, 369 insertions(+), 57 deletions(-) create mode 100644 staging/src/k8s.io/apiserver/pkg/endpoints/filters/with_auditid.go create mode 100644 staging/src/k8s.io/apiserver/pkg/endpoints/filters/with_auditid_test.go create mode 100644 staging/src/k8s.io/apiserver/pkg/endpoints/request/auditid.go create mode 100644 staging/src/k8s.io/apiserver/pkg/endpoints/request/auditid_test.go diff --git a/staging/src/k8s.io/apiserver/pkg/audit/request.go b/staging/src/k8s.io/apiserver/pkg/audit/request.go index 205bf25c8b5..960ec93211f 100644 --- a/staging/src/k8s.io/apiserver/pkg/audit/request.go +++ b/staging/src/k8s.io/apiserver/pkg/audit/request.go @@ -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" @@ -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 ( @@ -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)) diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit.go b/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit.go index 2f78ff1de64..853d1da9fd4 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit.go +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit.go @@ -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 { @@ -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) } @@ -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() } diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit_test.go b/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit_test.go index e1531b42103..272f2efc984 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit_test.go +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit_test.go @@ -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) @@ -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", @@ -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) + 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) + + 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) + } + + 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")) + } + } }) - 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) - } - - 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")) - } - } 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")) - } - } } } diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/filters/with_auditid.go b/staging/src/k8s.io/apiserver/pkg/endpoints/filters/with_auditid.go new file mode 100644 index 00000000000..a7e8c7e4a58 --- /dev/null +++ b/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) + }) +} diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/filters/with_auditid_test.go b/staging/src/k8s.io/apiserver/pkg/endpoints/filters/with_auditid_test.go new file mode 100644 index 00000000000..29c8c9c8b03 --- /dev/null +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/filters/with_auditid_test.go @@ -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) + } + }) + } +} diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/request/auditid.go b/staging/src/k8s.io/apiserver/pkg/endpoints/request/auditid.go new file mode 100644 index 00000000000..a7b3d84addb --- /dev/null +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/request/auditid.go @@ -0,0 +1,66 @@ +/* +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 request + +import ( + "context" + "net/http" + + "k8s.io/apimachinery/pkg/types" +) + +type auditIDKeyType int + +// auditIDKey is the key to associate the Audit-ID value of a request. +const auditIDKey auditIDKeyType = iota + +// WithAuditID returns a copy of the parent context into which the Audit-ID +// associated with the request is set. +// +// If the specified auditID is empty, no value is set and the parent context is returned as is. +func WithAuditID(parent context.Context, auditID types.UID) context.Context { + if auditID == "" { + return parent + } + return WithValue(parent, auditIDKey, auditID) +} + +// AuditIDFrom returns the value of the audit ID from the request context. +func AuditIDFrom(ctx context.Context) (types.UID, bool) { + auditID, ok := ctx.Value(auditIDKey).(types.UID) + return auditID, ok +} + +// GetAuditIDTruncated returns the audit ID (truncated) associated with a request. +// If the length of the Audit-ID value exceeds the limit, we truncate it to keep +// the first N (maxAuditIDLength) characters. +// This is intended to be used in logging only. +func GetAuditIDTruncated(req *http.Request) string { + auditID, ok := AuditIDFrom(req.Context()) + if !ok { + return "" + } + + // if the user has specified a very long audit ID then we will use the first N characters + // Note: assuming Audit-ID header is in ASCII + const maxAuditIDLength = 64 + if len(auditID) > maxAuditIDLength { + auditID = auditID[0:maxAuditIDLength] + } + + return string(auditID) +} diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/request/auditid_test.go b/staging/src/k8s.io/apiserver/pkg/endpoints/request/auditid_test.go new file mode 100644 index 00000000000..1583bdb2169 --- /dev/null +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/request/auditid_test.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 request + +import ( + "context" + "testing" + + "k8s.io/apimachinery/pkg/types" +) + +func TestAuditIDFrom(t *testing.T) { + tests := []struct { + name string + auditID string + auditIDExpected string + expected bool + }{ + { + name: "empty audit ID", + auditID: "", + auditIDExpected: "", + expected: false, + }, + { + name: "non empty audit ID", + auditID: "foo-bar-baz", + auditIDExpected: "foo-bar-baz", + expected: true, + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + parent := context.TODO() + ctx := WithAuditID(parent, types.UID(test.auditID)) + + // for an empty audit ID we don't expect a copy of the parent context. + if len(test.auditID) == 0 && parent != ctx { + t.Error("expected no copy of the parent context with an empty audit ID") + } + + value, ok := AuditIDFrom(ctx) + if test.expected != ok { + t.Errorf("expected AuditIDFrom to return: %t, but got: %t", test.expected, ok) + } + + auditIDGot := string(value) + if test.auditIDExpected != auditIDGot { + t.Errorf("expected audit ID: %q, but got: %q", test.auditIDExpected, auditIDGot) + } + }) + } +} diff --git a/staging/src/k8s.io/apiserver/pkg/server/config.go b/staging/src/k8s.io/apiserver/pkg/server/config.go index d1bbc27017d..aca7995898b 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/config.go +++ b/staging/src/k8s.io/apiserver/pkg/server/config.go @@ -764,6 +764,7 @@ func DefaultBuildHandlerChain(apiHandler http.Handler, c *Config) http.Handler { handler = genericfilters.WithHSTS(handler, c.HSTSDirectives) handler = genericapifilters.WithRequestReceivedTimestamp(handler) handler = genericfilters.WithPanicRecovery(handler, c.RequestInfoResolver) + handler = genericapifilters.WithAuditID(handler) return handler } diff --git a/staging/src/k8s.io/apiserver/pkg/server/filters/priority-and-fairness_test.go b/staging/src/k8s.io/apiserver/pkg/server/filters/priority-and-fairness_test.go index e6e2df6c518..367bb4abd15 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/filters/priority-and-fairness_test.go +++ b/staging/src/k8s.io/apiserver/pkg/server/filters/priority-and-fairness_test.go @@ -810,6 +810,7 @@ func newHandlerChain(t *testing.T, handler http.Handler, filter utilflowcontrol. handler = apifilters.WithRequestDeadline(handler, nil, nil, longRunningRequestCheck, nil, requestTimeout) handler = apifilters.WithRequestInfo(handler, requestInfoFactory) handler = WithPanicRecovery(handler, requestInfoFactory) + handler = apifilters.WithAuditID(handler) return handler } From b607ca1bf3e1cf6152c446ea61ac7fdd9014e1f1 Mon Sep 17 00:00:00 2001 From: Abu Kashem Date: Tue, 2 Mar 2021 19:27:43 -0500 Subject: [PATCH 2/2] 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. --- .../pkg/endpoints/handlers/helpers.go | 15 +++++++ .../pkg/endpoints/handlers/trace_util.go | 1 + .../pkg/server/filters/timeout_test.go | 4 +- .../apiserver/pkg/server/filters/wrap.go | 4 +- .../apiserver/pkg/server/httplog/httplog.go | 4 ++ .../pkg/apiserver/handler_proxy.go | 7 ++++ .../pkg/apiserver/handler_proxy_test.go | 41 +++++++++++++++++++ 7 files changed, 72 insertions(+), 4 deletions(-) diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/helpers.go b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/helpers.go index 244a3fd0a51..3fb7beccad1 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/helpers.go +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/helpers.go @@ -20,6 +20,7 @@ import ( "net/http" utilnet "k8s.io/apimachinery/pkg/util/net" + "k8s.io/apiserver/pkg/endpoints/request" ) const ( @@ -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" +} diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/trace_util.go b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/trace_util.go index 69b41fac4e3..8d7c4e1b526 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/trace_util.go +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/trace_util.go @@ -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}} diff --git a/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go b/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go index faf8c1ad81a..1cd24358413 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go +++ b/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go @@ -263,7 +263,7 @@ func TestErrConnKilled(t *testing.T) { if strings.Count(capturedOutput, "\n") != 1 { t.Errorf("unexpected output captured actual = %v", capturedOutput) } - if !strings.Contains(capturedOutput, `timeout or abort while handling: GET "/"`) { + if !strings.Contains(capturedOutput, `timeout or abort while handling: method=GET URI="/" audit-ID=""`) { t.Errorf("unexpected output captured actual = %v", capturedOutput) } } @@ -353,7 +353,7 @@ func TestErrConnKilledHTTP2(t *testing.T) { if strings.Count(capturedOutput, "\n") != 1 { t.Errorf("unexpected output captured actual = %v", capturedOutput) } - if !strings.Contains(capturedOutput, `timeout or abort while handling: GET "/"`) { + if !strings.Contains(capturedOutput, `timeout or abort while handling: method=GET URI="/" audit-ID=""`) { t.Errorf("unexpected output captured actual = %v", capturedOutput) } diff --git a/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go b/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go index 34c5398dba9..408011fc6c0 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go +++ b/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go @@ -51,11 +51,11 @@ func WithPanicRecovery(handler http.Handler, resolver request.RequestInfoResolve // This call can have different handlers, but the default chain rate limits. Call it after the metrics are updated // in case the rate limit delays it. If you outrun the rate for this one timed out requests, something has gone // seriously wrong with your server, but generally having a logging signal for timeouts is useful. - runtime.HandleError(fmt.Errorf("timeout or abort while handling: %v %q", req.Method, req.URL.Path)) + runtime.HandleError(fmt.Errorf("timeout or abort while handling: method=%v URI=%q audit-ID=%q", req.Method, req.RequestURI, request.GetAuditIDTruncated(req))) return } http.Error(w, "This request caused apiserver to panic. Look in the logs for details.", http.StatusInternalServerError) - klog.Errorf("apiserver panic'd on %v %v", req.Method, req.RequestURI) + klog.ErrorS(nil, "apiserver panic'd", "method", req.Method, "URI", req.RequestURI, "audit-ID", request.GetAuditIDTruncated(req)) }) } diff --git a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go index 4cb5306672b..af205fade6c 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go +++ b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go @@ -25,6 +25,7 @@ import ( "runtime" "time" + "k8s.io/apiserver/pkg/endpoints/request" "k8s.io/klog/v2" ) @@ -157,12 +158,14 @@ func (rl *respLogger) Addf(format string, data ...interface{}) { func (rl *respLogger) LogArgs() []interface{} { latency := time.Since(rl.startTime) + auditID := request.GetAuditIDTruncated(rl.req) if rl.hijacked { return []interface{}{ "verb", rl.req.Method, "URI", rl.req.RequestURI, "latency", latency, "userAgent", rl.req.UserAgent(), + "audit-ID", auditID, "srcIP", rl.req.RemoteAddr, "hijacked", true, } @@ -172,6 +175,7 @@ func (rl *respLogger) LogArgs() []interface{} { "URI", rl.req.RequestURI, "latency", latency, "userAgent", rl.req.UserAgent(), + "audit-ID", auditID, "srcIP", rl.req.RemoteAddr, "resp", rl.status, } diff --git a/staging/src/k8s.io/kube-aggregator/pkg/apiserver/handler_proxy.go b/staging/src/k8s.io/kube-aggregator/pkg/apiserver/handler_proxy.go index e09f0d1a238..0c7588ab17c 100644 --- a/staging/src/k8s.io/kube-aggregator/pkg/apiserver/handler_proxy.go +++ b/staging/src/k8s.io/kube-aggregator/pkg/apiserver/handler_proxy.go @@ -29,6 +29,7 @@ import ( "k8s.io/apimachinery/pkg/util/httpstream/spdy" utilnet "k8s.io/apimachinery/pkg/util/net" "k8s.io/apimachinery/pkg/util/proxy" + auditinternal "k8s.io/apiserver/pkg/apis/audit" "k8s.io/apiserver/pkg/endpoints/handlers/responsewriters" endpointmetrics "k8s.io/apiserver/pkg/endpoints/metrics" genericapirequest "k8s.io/apiserver/pkg/endpoints/request" @@ -201,6 +202,12 @@ func newRequestForProxy(location *url.URL, req *http.Request) (*http.Request, co newReq.URL = location newReq.Host = location.Host + // If the original request has an audit ID, let's make sure we propagate this + // to the aggregated server. + if auditID, found := genericapirequest.AuditIDFrom(req.Context()); found { + newReq.Header.Set(auditinternal.HeaderAuditID, string(auditID)) + } + return newReq, cancelFn } diff --git a/staging/src/k8s.io/kube-aggregator/pkg/apiserver/handler_proxy_test.go b/staging/src/k8s.io/kube-aggregator/pkg/apiserver/handler_proxy_test.go index 95282152b85..30fa28b2308 100644 --- a/staging/src/k8s.io/kube-aggregator/pkg/apiserver/handler_proxy_test.go +++ b/staging/src/k8s.io/kube-aggregator/pkg/apiserver/handler_proxy_test.go @@ -36,6 +36,7 @@ import ( "golang.org/x/net/websocket" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "k8s.io/apimachinery/pkg/types" "k8s.io/apimachinery/pkg/util/proxy" "k8s.io/apimachinery/pkg/util/sets" "k8s.io/apiserver/pkg/authentication/user" @@ -577,6 +578,46 @@ func TestGetContextForNewRequest(t *testing.T) { } +func TestNewRequestForProxyWithAuditID(t *testing.T) { + tests := []struct { + name string + auditID string + }{ + { + name: "original request has Audit-ID", + auditID: "foo-bar", + }, + { + name: "original request does not have Audit-ID", + auditID: "", + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + req, err := http.NewRequest(http.MethodGet, "/api/group/version/foos/namespace/foo", nil) + if err != nil { + t.Fatalf("failed to create new http request - %v", err) + } + + req = req.WithContext(genericapirequest.WithRequestInfo(req.Context(), &genericapirequest.RequestInfo{Path: req.URL.Path})) + if len(test.auditID) > 0 { + req = req.WithContext(genericapirequest.WithAuditID(req.Context(), types.UID(test.auditID))) + } + + newReq, _ := newRequestForProxy(req.URL, req) + if newReq == nil { + t.Fatal("expected a non nil Request object") + } + + auditIDGot := newReq.Header.Get("Audit-ID") + if test.auditID != auditIDGot { + t.Errorf("expected an Audit-ID value: %q, but got: %q", test.auditID, auditIDGot) + } + }) + } +} + // TestProxyCertReload verifies that the proxy reloading of certificates work // to be able to test the reloading it starts a server with client auth enabled // it first uses certs that does not match the client CA so the verification fails - expecting HTTP 503