Skip to content

Commit ff6768d

Browse files
timebertttimebertt
committed
✨ Pass webhook logger to handler via context
1 parent f035121 commit ff6768d

File tree

6 files changed

+148
-24
lines changed

6 files changed

+148
-24
lines changed

‎examples/builtins/mutatingwebhook.go

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -22,7 +22,9 @@ import (
2222
"net/http"
2323

2424
corev1 "k8s.io/api/core/v1"
25+
2526
"sigs.k8s.io/controller-runtime/pkg/client"
27+
logf "sigs.k8s.io/controller-runtime/pkg/log"
2628
"sigs.k8s.io/controller-runtime/pkg/webhook/admission"
2729
)
2830

@@ -36,8 +38,10 @@ type podAnnotator struct {
3638

3739
// podAnnotator adds an annotation to every incoming pods.
3840
func (a *podAnnotator) Handle(ctx context.Context, req admission.Request) admission.Response {
39-
pod := &corev1.Pod{}
41+
// set up a convenient log object so we don't have to type request over and over again
42+
log := logf.FromContext(ctx)
4043

44+
pod := &corev1.Pod{}
4145
err := a.decoder.Decode(req, pod)
4246
if err != nil {
4347
return admission.Errored(http.StatusBadRequest, err)
@@ -52,6 +56,7 @@ func (a *podAnnotator) Handle(ctx context.Context, req admission.Request) admiss
5256
if err != nil {
5357
return admission.Errored(http.StatusInternalServerError, err)
5458
}
59+
log.Info("Annotating Pod")
5560

5661
return admission.PatchResponseFromRaw(req.Object.Raw, marshaledPod)
5762
}

‎examples/builtins/validatingwebhook.go

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -22,7 +22,9 @@ import (
2222
"net/http"
2323

2424
corev1 "k8s.io/api/core/v1"
25+
2526
"sigs.k8s.io/controller-runtime/pkg/client"
27+
logf "sigs.k8s.io/controller-runtime/pkg/log"
2628
"sigs.k8s.io/controller-runtime/pkg/webhook/admission"
2729
)
2830

@@ -36,13 +38,17 @@ type podValidator struct {
3638

3739
// podValidator admits a pod if a specific annotation exists.
3840
func (v *podValidator) Handle(ctx context.Context, req admission.Request) admission.Response {
39-
pod := &corev1.Pod{}
41+
// set up a convenient log object so we don't have to type request over and over again
42+
log := logf.FromContext(ctx)
4043

44+
pod := &corev1.Pod{}
4145
err := v.decoder.Decode(req, pod)
4246
if err != nil {
4347
return admission.Errored(http.StatusBadRequest, err)
4448
}
4549

50+
log.Info("Validating Pod")
51+
4652
key := "example-mutating-admission-webhook"
4753
anno, found := pod.Annotations[key]
4854
if !found {

‎pkg/webhook/admission/defaulter_test.go

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -10,13 +10,16 @@ import (
1010
admissionv1 "k8s.io/api/admission/v1"
1111
"k8s.io/apimachinery/pkg/runtime"
1212
"k8s.io/apimachinery/pkg/runtime/schema"
13+
14+
"sigs.k8s.io/controller-runtime/pkg/runtime/inject"
1315
)
1416

1517
var _ = Describe("Defaulter Handler", func() {
1618

1719
It("should return ok if received delete verb in defaulter handler", func() {
1820
obj := &TestDefaulter{}
1921
handler := DefaultingWebhookFor(obj)
22+
Expect(inject.LoggerInto(log, handler)).To(BeTrue())
2023

2124
resp := handler.Handle(context.TODO(), Request{
2225
AdmissionRequest: admissionv1.AdmissionRequest{

‎pkg/webhook/admission/http.go

Lines changed: 8 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -52,15 +52,15 @@ func (wh *Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) {
5252
var reviewResponse Response
5353
if r.Body == nil {
5454
err = errors.New("request body is empty")
55-
wh.log.Error(err, "bad request")
55+
wh.getLogger(nil).Error(err, "bad request")
5656
reviewResponse = Errored(http.StatusBadRequest, err)
5757
wh.writeResponse(w, reviewResponse)
5858
return
5959
}
6060

6161
defer r.Body.Close()
6262
if body, err = io.ReadAll(r.Body); err != nil {
63-
wh.log.Error(err, "unable to read the body from the incoming request")
63+
wh.getLogger(nil).Error(err, "unable to read the body from the incoming request")
6464
reviewResponse = Errored(http.StatusBadRequest, err)
6565
wh.writeResponse(w, reviewResponse)
6666
return
@@ -69,7 +69,7 @@ func (wh *Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) {
6969
// verify the content type is accurate
7070
if contentType := r.Header.Get("Content-Type"); contentType != "application/json" {
7171
err = fmt.Errorf("contentType=%s, expected application/json", contentType)
72-
wh.log.Error(err, "unable to process a request with an unknown content type", "content type", contentType)
72+
wh.getLogger(nil).Error(err, "unable to process a request with an unknown content type", "content type", contentType)
7373
reviewResponse = Errored(http.StatusBadRequest, err)
7474
wh.writeResponse(w, reviewResponse)
7575
return
@@ -88,12 +88,12 @@ func (wh *Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) {
8888
ar.SetGroupVersionKind(v1.SchemeGroupVersion.WithKind("AdmissionReview"))
8989
_, actualAdmRevGVK, err := admissionCodecs.UniversalDeserializer().Decode(body, nil, &ar)
9090
if err != nil {
91-
wh.log.Error(err, "unable to decode the request")
91+
wh.getLogger(nil).Error(err, "unable to decode the request")
9292
reviewResponse = Errored(http.StatusBadRequest, err)
9393
wh.writeResponse(w, reviewResponse)
9494
return
9595
}
96-
wh.log.V(1).Info("received request", "UID", req.UID, "kind", req.Kind, "resource", req.Resource)
96+
wh.getLogger(nil).V(1).Info("received request", "UID", req.UID, "kind", req.Kind, "resource", req.Resource)
9797

9898
reviewResponse = wh.Handle(ctx, req)
9999
wh.writeResponseTyped(w, reviewResponse, actualAdmRevGVK)
@@ -124,19 +124,19 @@ func (wh *Webhook) writeResponseTyped(w io.Writer, response Response, admRevGVK
124124
// writeAdmissionResponse writes ar to w.
125125
func (wh *Webhook) writeAdmissionResponse(w io.Writer, ar v1.AdmissionReview) {
126126
if err := json.NewEncoder(w).Encode(ar); err != nil {
127-
wh.log.Error(err, "unable to encode and write the response")
127+
wh.getLogger(nil).Error(err, "unable to encode and write the response")
128128
// Since the `ar v1.AdmissionReview` is a clear and legal object,
129129
// it should not have problem to be marshalled into bytes.
130130
// The error here is probably caused by the abnormal HTTP connection,
131131
// e.g., broken pipe, so we can only write the error response once,
132132
// to avoid endless circular calling.
133133
serverError := Errored(http.StatusInternalServerError, err)
134134
if err = json.NewEncoder(w).Encode(v1.AdmissionReview{Response: &serverError.AdmissionResponse}); err != nil {
135-
wh.log.Error(err, "still unable to encode and write the InternalServerError response")
135+
wh.getLogger(nil).Error(err, "still unable to encode and write the InternalServerError response")
136136
}
137137
} else {
138138
res := ar.Response
139-
if log := wh.log; log.V(1).Enabled() {
139+
if log := wh.getLogger(nil); log.V(1).Enabled() {
140140
if res.Result != nil {
141141
log = log.WithValues("code", res.Result.Code, "reason", res.Result.Reason)
142142
}

‎pkg/webhook/admission/webhook.go

Lines changed: 35 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -23,15 +23,17 @@ import (
2323
"net/http"
2424

2525
"github.com/go-logr/logr"
26-
jsonpatch "gomodules.xyz/jsonpatch/v2"
26+
"gomodules.xyz/jsonpatch/v2"
2727
admissionv1 "k8s.io/api/admission/v1"
2828
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
2929
"k8s.io/apimachinery/pkg/runtime"
3030
"k8s.io/apimachinery/pkg/util/json"
3131
utilruntime "k8s.io/apimachinery/pkg/util/runtime"
3232
"k8s.io/client-go/kubernetes/scheme"
33+
"k8s.io/klog/v2"
3334

34-
logf "sigs.k8s.io/controller-runtime/pkg/internal/log"
35+
internallog "sigs.k8s.io/controller-runtime/pkg/internal/log"
36+
logf "sigs.k8s.io/controller-runtime/pkg/log"
3537
"sigs.k8s.io/controller-runtime/pkg/runtime/inject"
3638
"sigs.k8s.io/controller-runtime/pkg/webhook/internal/metrics"
3739
)
@@ -131,6 +133,12 @@ type Webhook struct {
131133
// headers thus allowing you to read them from within the handler
132134
WithContextFunc func(context.Context, *http.Request) context.Context
133135

136+
// LogConstructor is used to construct a logger for logging messages during webhook calls
137+
// based on the given base logger (which might carry more values like the webhook's path).
138+
// Note: LogConstructor has to be able to handle nil requests as we are also using it
139+
// outside the context of requests.
140+
LogConstructor func(base logr.Logger, req *Request) logr.Logger
141+
134142
// decoder is constructed on receiving a scheme and passed down to then handler
135143
decoder *Decoder
136144

@@ -166,15 +174,38 @@ func (wh *Webhook) Handle(ctx context.Context, req Request) (response Response)
166174
}()
167175
}
168176

177+
reqLog := wh.getLogger(&req)
178+
reqLog = reqLog.WithValues("requestID", req.UID)
179+
ctx = logf.IntoContext(ctx, reqLog)
180+
169181
resp := wh.Handler.Handle(ctx, req)
170182
if err := resp.Complete(req); err != nil {
171-
wh.log.Error(err, "unable to encode response")
183+
reqLog.Error(err, "unable to encode response")
172184
return Errored(http.StatusInternalServerError, errUnableToEncodeResponse)
173185
}
174186

175187
return resp
176188
}
177189

190+
// getLogger constructs a logger from the injected log and LogConstructor.
191+
func (wh *Webhook) getLogger(req *Request) logr.Logger {
192+
logConstructor := wh.LogConstructor
193+
if logConstructor == nil {
194+
logConstructor = DefaultLogConstructor
195+
}
196+
return logConstructor(wh.log, req)
197+
}
198+
199+
// DefaultLogConstructor adds some commonly interesting fields to the given logger.
200+
func DefaultLogConstructor(base logr.Logger, req *Request) logr.Logger {
201+
if req != nil {
202+
return base.WithValues("object", klog.KRef(req.Namespace, req.Name),
203+
"resource", req.Resource, "user", req.UserInfo.Username,
204+
)
205+
}
206+
return base
207+
}
208+
178209
// InjectScheme injects a scheme into the webhook, in order to construct a Decoder.
179210
func (wh *Webhook) InjectScheme(s *runtime.Scheme) error {
180211
// TODO(directxman12): we should have a better way to pass this down
@@ -267,7 +298,7 @@ func StandaloneWebhook(hook *Webhook, opts StandaloneOptions) (http.Handler, err
267298
}
268299

269300
if opts.Logger.GetSink() == nil {
270-
opts.Logger = logf.RuntimeLog.WithName("webhook")
301+
opts.Logger = internallog.RuntimeLog.WithName("webhook")
271302
}
272303
hook.log = opts.Logger
273304

‎pkg/webhook/admission/webhook_test.go

Lines changed: 89 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -18,22 +18,37 @@ package admission
1818

1919
import (
2020
"context"
21+
"io"
2122
"net/http"
2223

24+
"github.com/go-logr/logr"
2325
. "github.com/onsi/ginkgo"
2426
. "github.com/onsi/gomega"
25-
26-
jsonpatch "gomodules.xyz/jsonpatch/v2"
27+
"github.com/onsi/gomega/gbytes"
28+
"gomodules.xyz/jsonpatch/v2"
2729
admissionv1 "k8s.io/api/admission/v1"
30+
authenticationv1 "k8s.io/api/authentication/v1"
2831
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
2932
"k8s.io/apimachinery/pkg/runtime"
3033
machinerytypes "k8s.io/apimachinery/pkg/types"
3134

32-
logf "sigs.k8s.io/controller-runtime/pkg/internal/log"
35+
internallog "sigs.k8s.io/controller-runtime/pkg/internal/log"
36+
logf "sigs.k8s.io/controller-runtime/pkg/log"
37+
"sigs.k8s.io/controller-runtime/pkg/log/zap"
3338
"sigs.k8s.io/controller-runtime/pkg/runtime/inject"
3439
)
3540

3641
var _ = Describe("Admission Webhooks", func() {
42+
var (
43+
logBuffer *gbytes.Buffer
44+
testLogger logr.Logger
45+
)
46+
47+
BeforeEach(func() {
48+
logBuffer = gbytes.NewBuffer()
49+
testLogger = zap.New(zap.JSONEncoder(), zap.WriteTo(io.MultiWriter(logBuffer, GinkgoWriter)))
50+
})
51+
3752
allowHandler := func() *Webhook {
3853
handler := &fakeHandler{
3954
fn: func(ctx context.Context, req Request) Response {
@@ -46,7 +61,7 @@ var _ = Describe("Admission Webhooks", func() {
4661
}
4762
webhook := &Webhook{
4863
Handler: handler,
49-
log: logf.RuntimeLog.WithName("webhook"),
64+
log: internallog.RuntimeLog.WithName("webhook"),
5065
}
5166

5267
return webhook
@@ -96,7 +111,7 @@ var _ = Describe("Admission Webhooks", func() {
96111
},
97112
}
98113
}),
99-
log: logf.RuntimeLog.WithName("webhook"),
114+
log: internallog.RuntimeLog.WithName("webhook"),
100115
}
101116

102117
By("invoking the webhook")
@@ -113,7 +128,7 @@ var _ = Describe("Admission Webhooks", func() {
113128
Handler: HandlerFunc(func(ctx context.Context, req Request) Response {
114129
return Patched("", jsonpatch.Operation{Operation: "add", Path: "/a", Value: 2}, jsonpatch.Operation{Operation: "replace", Path: "/b", Value: 4})
115130
}),
116-
log: logf.RuntimeLog.WithName("webhook"),
131+
log: internallog.RuntimeLog.WithName("webhook"),
117132
}
118133

119134
By("invoking the webhook")
@@ -125,6 +140,70 @@ var _ = Describe("Admission Webhooks", func() {
125140
Expect(resp.Patch).To(Equal([]byte(`[{"op":"add","path":"/a","value":2},{"op":"replace","path":"/b","value":4}]`)))
126141
})
127142

143+
It("should pass a request logger via the context", func() {
144+
By("setting up a webhook that uses the request logger")
145+
webhook := &Webhook{
146+
Handler: HandlerFunc(func(ctx context.Context, req Request) Response {
147+
logf.FromContext(ctx).Info("Received request")
148+
149+
return Response{
150+
AdmissionResponse: admissionv1.AdmissionResponse{
151+
Allowed: true,
152+
},
153+
}
154+
}),
155+
log: testLogger,
156+
}
157+
158+
By("invoking the webhook")
159+
resp := webhook.Handle(context.Background(), Request{AdmissionRequest: admissionv1.AdmissionRequest{
160+
UID: "test123",
161+
Name: "foo",
162+
Namespace: "bar",
163+
Resource: metav1.GroupVersionResource{
164+
Group: "apps",
165+
Version: "v1",
166+
Resource: "deployments",
167+
},
168+
UserInfo: authenticationv1.UserInfo{
169+
Username: "tim",
170+
},
171+
}})
172+
Expect(resp.Allowed).To(BeTrue())
173+
174+
By("checking that the log message contains the request fields")
175+
Eventually(logBuffer).Should(gbytes.Say(`"msg":"Received request","object":{"name":"foo","namespace":"bar"},"resource":{"group":"apps","version":"v1","resource":"deployments"},"user":"tim","requestID":"test123"}`))
176+
})
177+
178+
It("should pass a request logger created by LogConstructor via the context", func() {
179+
By("setting up a webhook that uses the request logger")
180+
webhook := &Webhook{
181+
Handler: HandlerFunc(func(ctx context.Context, req Request) Response {
182+
logf.FromContext(ctx).Info("Received request")
183+
184+
return Response{
185+
AdmissionResponse: admissionv1.AdmissionResponse{
186+
Allowed: true,
187+
},
188+
}
189+
}),
190+
LogConstructor: func(base logr.Logger, req *Request) logr.Logger {
191+
return base.WithValues("operation", req.Operation)
192+
},
193+
log: testLogger,
194+
}
195+
196+
By("invoking the webhook")
197+
resp := webhook.Handle(context.Background(), Request{AdmissionRequest: admissionv1.AdmissionRequest{
198+
UID: "test123",
199+
Operation: admissionv1.Create,
200+
}})
201+
Expect(resp.Allowed).To(BeTrue())
202+
203+
By("checking that the log message contains the request fields")
204+
Eventually(logBuffer).Should(gbytes.Say(`"msg":"Received request","operation":"CREATE","requestID":"test123"}`))
205+
})
206+
128207
Describe("dependency injection", func() {
129208
It("should set dependencies passed in on the handler", func() {
130209
By("setting up a webhook and injecting it with a injection func that injects a string")
@@ -139,7 +218,7 @@ var _ = Describe("Admission Webhooks", func() {
139218
handler := &fakeHandler{}
140219
webhook := &Webhook{
141220
Handler: handler,
142-
log: logf.RuntimeLog.WithName("webhook"),
221+
log: internallog.RuntimeLog.WithName("webhook"),
143222
}
144223
Expect(setFields(webhook)).To(Succeed())
145224
Expect(inject.InjectorInto(setFields, webhook)).To(BeTrue())
@@ -159,7 +238,7 @@ var _ = Describe("Admission Webhooks", func() {
159238
handler := &fakeHandler{}
160239
webhook := &Webhook{
161240
Handler: handler,
162-
log: logf.RuntimeLog.WithName("webhook"),
241+
log: internallog.RuntimeLog.WithName("webhook"),
163242
}
164243
Expect(setFields(webhook)).To(Succeed())
165244
Expect(inject.InjectorInto(setFields, webhook)).To(BeTrue())
@@ -204,7 +283,7 @@ var _ = Describe("Admission Webhooks", func() {
204283
webhook := &Webhook{
205284
Handler: handler,
206285
RecoverPanic: true,
207-
log: logf.RuntimeLog.WithName("webhook"),
286+
log: internallog.RuntimeLog.WithName("webhook"),
208287
}
209288

210289
return webhook
@@ -231,7 +310,7 @@ var _ = Describe("Admission Webhooks", func() {
231310
}
232311
webhook := &Webhook{
233312
Handler: handler,
234-
log: logf.RuntimeLog.WithName("webhook"),
313+
log: internallog.RuntimeLog.WithName("webhook"),
235314
}
236315

237316
return webhook

0 commit comments

Comments
 (0)