Cert-manager: High rate of error log messages in webhook

Created on 15 Mar 2019 · 9Comments · Source: jetstack/cert-manager

Bugs should be filed for issues encountered whilst operating cert-manager.
You should first attempt to resolve your issues through the community support
channels, e.g. Slack, in order to rule out individual configuration errors.
Please provide as much detail as possible.

Describe the bug:

The default recommended config of webhook has --v=12. This outputs several hundred messages/s.

Expected behaviour:

Under normal use no log messages are generated (e.g. log on exceptional or startup only)

Steps to reproduce the bug:

v0.7.0
GKE regional 3-master, 3 node.

The root of the issue is the check of / w/o the RBAC

I0315 21:15:13.323979       1 authorization.go:73] Forbidden: "/", Reason: "no RBAC policy matched"
I0315 21:15:13.324100       1 wrap.go:47] GET /: (359.07702ms) 403 [Go-http-client/2.0 10.162.0.10:48420]

event w/ --v=3 we end up with a lot (since those two messages above occur 9 times/s).

This is some sort of health (?) check from kubelet. The IP match the nodes.

There are 9 clusters of messages per second.

w/ the default of --v=12, we end up with more logs like this:

I0315 20:05:20.407103       1 request.go:942] Request Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1beta1","metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/","verb":"get"},"user":"system:anonymous","group":["system:unauthenticated"]},"status":{"allowed":false}}
I0315 20:05:20.407247       1 round_trippers.go:419] curl -k -v -XPOST  -H "Accept: application/json, */*" -H "Content-Type: application/json" -H "User-Agent: image.app_linux-amd64.binary/v0.0.0 (linux/amd64) kubernetes/$Format" -H "Authorization: Bearer REDACTED" 'https://10.63.240.1:443/apis/authorization.k8s.io/v1beta1/subjectaccessreviews'
I0315 20:05:20.683946       1 request.go:942] Request Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1beta1","metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/","verb":"get"},"user":"system:anonymous","group":["system:unauthenticated"]},"status":{"allowed":false}}
I0315 20:05:20.684094       1 round_trippers.go:419] curl -k -v -XPOST  -H "User-Agent: image.app_linux-amd64.binary/v0.0.0 (linux/amd64) kubernetes/$Format" -H "Accept: application/json, */*" -H "Content-Type: application/json" -H "Authorization: Bearer REDACTED" 'https://10.63.240.1:443/apis/authorization.k8s.io/v1beta1/subjectaccessreviews'
I0315 20:05:20.721752       1 round_trippers.go:438] POST https://10.63.240.1:443/apis/authorization.k8s.io/v1beta1/subjectaccessreviews 201 Created in 314 milliseconds
I0315 20:05:20.721780       1 round_trippers.go:444] Response Headers:
I0315 20:05:20.721785       1 round_trippers.go:447]     Audit-Id: 3f381b37-REDACTED
I0315 20:05:20.721789       1 round_trippers.go:447]     Content-Type: application/json
I0315 20:05:20.721797       1 round_trippers.go:447]     Content-Length: 294
I0315 20:05:20.721800       1 round_trippers.go:447]     Date: Fri, 15 Mar 2019 20:05:20 GMT

Anything else we need to know?:

Environment details::

Kubernetes version (e.g. v1.10.2): v1.12.5-gke.5
Cloud-provider/provisioner (e.g. GKE, kops AWS, etc): GKE
cert-manager version (e.g. v0.4.0): v0.7.0
Install method (e.g. helm or static manifests): static manifest

$ kubectl version
Client Version: version.Info{Major:"1", Minor:"13", GitVersion:"v1.13.4", GitCommit:"c27b913fddd1a6c480c229191a087698aa92f0b1", GitTreeState:"clean", BuildDate:"2019-02-28T13:37:52Z", GoVersion:"go1.11.5", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"12+", GitVersion:"v1.12.5-gke.5", GitCommit:"2c44750044d8aeeb6b51386ddb9c274ff0beb50b", GitTreeState:"clean", BuildDate:"2019-02-01T23:53:25Z", GoVersion:"go1.10.8b4", Compiler:"gc", Platform:"linux/amd64"}

/kind bug

kinbug lifecyclrotten

Source

donbowman

👍9

Most helpful comment

Same issue here w/ GKE

gak10100 on 26 Mar 2019

👍6

All 9 comments

Same problem here with GKE same version.. any hint?

Repeatedly ask their permissions of get / for k8s API server.

[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:51:05.866626       1 request.go:942] Request Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1beta1","metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/apis/admission.certmanager.k8s.io/v1beta1","verb":"get"},"user":"system:serviceaccount:kube-system:generic-garbage-collector","group":["system:serviceaccounts","system:serviceaccounts:kube-system","system:authenticated"]},"status":{"allowed":false}}
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:51:05.866858       1 round_trippers.go:419] curl -k -v -XPOST  -H "Accept: application/json, */*" -H "Content-Type: application/json" -H "User-Agent: image.app_linux-amd64.binary/v0.0.0 (linux/amd64) kubernetes/$Format" -H "Authorization: Bearer ===REDACTED===" 'https://10.0.0.1:443/apis/authorization.k8s.io/v1beta1/subjectaccessreviews'
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:51:05.869323       1 round_trippers.go:438] POST https://10.0.0.1:443/apis/authorization.k8s.io/v1beta1/subjectaccessreviews 201 Created in 2 milliseconds
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:51:05.869344       1 round_trippers.go:444] Response Headers:
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:51:05.869349       1 round_trippers.go:447]     Audit-Id: e88095a0-0270-4f61-8bde-084293fd77fd
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:51:05.869352       1 round_trippers.go:447]     Content-Type: application/json
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:51:05.869355       1 round_trippers.go:447]     Content-Length: 541
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:51:05.869358       1 round_trippers.go:447]     Date: Tue, 19 Mar 2019 04:51:05 GMT
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:51:05.869396       1 request.go:942] Response Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1beta1","metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/apis/admission.certmanager.k8s.io/v1beta1","verb":"get"},"user":"system:serviceaccount:kube-system:generic-garbage-collector","group":["system:serviceaccounts","system:serviceaccounts:kube-system","system:authenticated"]},"status":{"allowed":true,"reason":"RBAC: allowed by ClusterRoleBinding \"system:discovery\" of ClusterRole \"system:discovery\" to Group \"system:authenticated\""}}
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:51:05.869513       1 handler.go:143] admission-server: GET "/apis/admission.certmanager.k8s.io/v1beta1" satisfied by gorestful with webservice /apis/admission.certmanager.k8s.io/v1beta1
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:51:05.869649       1 wrap.go:47] GET /apis/admission.certmanager.k8s.io/v1beta1?timeout=32s: (3.560096ms) 200 [kube-controller-manager/v1.12.5 (linux/amd64) kubernetes/2c44750/system:serviceaccount:kube-system:generic-garbage-collector 10.138.0.5:36816]
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:51:11.017766       1 handler.go:143] admission-server: GET "/apis/admission.certmanager.k8s.io/v1beta1" satisfied by gorestful with webservice /apis/admission.certmanager.k8s.io/v1beta1
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:51:11.021882       1 wrap.go:47] GET /apis/admission.certmanager.k8s.io/v1beta1?timeout=32s: (4.44367ms) 200 [kube-apiserver/v1.12.5 (linux/amd64) kubernetes/2c44750 10.138.0.5:36816]
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:53:48.186497       1 authorization.go:73] Forbidden: "/", Reason: "no RBAC policy matched"
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:53:48.186614       1 wrap.go:47] GET /: (16.766106ms) 403 [Go-http-client/2.0 10.138.0.3:49012]
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:53:48.213175       1 authorization.go:73] Forbidden: "/", Reason: "no RBAC policy matched"
[cert-manager-webhook-6f58884b96-b4bxp] I0319 04:53:48.213302       1 wrap.go:47] GET /: (277.07µs) 403 [Go-http-client/2.0 10.138.0.3:49012]
...

And webhook CA certificates warn that webhook issuers are not ready:

kubectl describe certs -n cert-manager
Name:         cert-manager-webhook-ca
Namespace:    cert-manager
Labels:       app=webhook
              chart=webhook-v0.7.0
              heritage=Tiller
              release=cert-manager
Annotations:  <none>
API Version:  certmanager.k8s.io/v1alpha1
Kind:         Certificate
Metadata:
  Creation Timestamp:  2019-03-19T04:39:54Z
  Generation:          1
  Resource Version:    3426022
  Self Link:           /apis/certmanager.k8s.io/v1alpha1/namespaces/cert-manager/certificates/cert-manager-webhook-ca
  UID:                 0a5d9d0a-4a01-11e9-9b57-42010a8a0078
Spec:
  Common Name:  ca.webhook.cert-manager
  Duration:     43800h0m0s
  Is CA:        true
  Issuer Ref:
    Name:       cert-manager-webhook-selfsign
  Secret Name:  cert-manager-webhook-ca
Status:
  Conditions:
    Last Transition Time:  2019-03-19T04:41:12Z
    Message:               Certificate is up to date and has not expired
    Reason:                Ready
    Status:                True
    Type:                  Ready
  Not After:               2024-03-16T09:53:17Z
Events:
  Type     Reason          Age   From          Message
  ----     ------          ----  ----          -------
  Warning  IssuerNotReady  4m    cert-manager  Issuer cert-manager-webhook-selfsign not ready


Name:         cert-manager-webhook-webhook-tls
Namespace:    cert-manager
Labels:       app=webhook
              chart=webhook-v0.7.0
              heritage=Tiller
              release=cert-manager
Annotations:  <none>
API Version:  certmanager.k8s.io/v1alpha1
Kind:         Certificate
Metadata:
  Creation Timestamp:  2019-03-19T04:39:54Z
  Generation:          1
  Resource Version:    3426017
  Self Link:           /apis/certmanager.k8s.io/v1alpha1/namespaces/cert-manager/certificates/cert-manager-webhook-webhook-tls
  UID:                 0a6ffb79-4a01-11e9-9b57-42010a8a0078
Spec:
  Dns Names:
    cert-manager-webhook
    cert-manager-webhook.cert-manager
    cert-manager-webhook.cert-manager.svc
  Duration:  8760h0m0s
  Issuer Ref:
    Name:       cert-manager-webhook-ca
  Secret Name:  cert-manager-webhook-webhook-tls
Status:
  Conditions:
    Last Transition Time:  2019-03-19T04:41:12Z
    Message:               Certificate is up to date and has not expired
    Reason:                Ready
    Status:                True
    Type:                  Ready
  Not After:               2020-03-17T09:53:22Z
Events:
  Type     Reason          Age   From          Message
  ----     ------          ----  ----          -------
  Warning  IssuerNotReady  4m    cert-manager  Issuer cert-manager-webhook-ca not ready

But issuers say they are ready:

kubectl describe issuers -n cert-manager
Name:         cert-manager-webhook-ca
Namespace:    cert-manager
Labels:       app=webhook
              chart=webhook-v0.7.0
              heritage=Tiller
              release=cert-manager
Annotations:  <none>
API Version:  certmanager.k8s.io/v1alpha1
Kind:         Issuer
Metadata:
  Creation Timestamp:  2019-03-19T04:39:54Z
  Generation:          1
  Resource Version:    3426016
  Self Link:           /apis/certmanager.k8s.io/v1alpha1/namespaces/cert-manager/issuers/cert-manager-webhook-ca
  UID:                 0a860cfd-4a01-11e9-9b57-42010a8a0078
Spec:
  Ca:
    Secret Name:  cert-manager-webhook-ca
Status:
  Conditions:
    Last Transition Time:  2019-03-19T04:41:12Z
    Message:               Signing CA verified
    Reason:                KeyPairVerified
    Status:                True
    Type:                  Ready
Events:
  Type    Reason           Age              From          Message
  ----    ------           ----             ----          -------
  Normal  KeyPairVerified  7m (x3 over 7m)  cert-manager  Signing CA verified


Name:         cert-manager-webhook-selfsign
Namespace:    cert-manager
Labels:       app=webhook
              chart=webhook-v0.7.0
              heritage=Tiller
              release=cert-manager
Annotations:  <none>
API Version:  certmanager.k8s.io/v1alpha1
Kind:         Issuer
Metadata:
  Creation Timestamp:  2019-03-19T04:39:54Z
  Generation:          1
  Resource Version:    3426018
  Self Link:           /apis/certmanager.k8s.io/v1alpha1/namespaces/cert-manager/issuers/cert-manager-webhook-selfsign
  UID:                 0a98a1a6-4a01-11e9-9b57-42010a8a0078
Spec:
  Self Signed:
Status:
  Conditions:
    Last Transition Time:  2019-03-19T04:41:12Z
    Message:
    Reason:                IsReady
    Status:                True
    Type:                  Ready
Events:                    <none>

What is the problem?

dehypnosis on 19 Mar 2019

Same issue here w/ GKE

gak10100 on 26 Mar 2019

👍6

😨

dperetti on 11 Apr 2019

same here, using on GKE, latest K8S release, cert-manager 0.7.1

str1k3r on 26 Apr 2019

👀1

Similar situation here with cert-manager 0.7.2 on bare metal k8s v1.14.2 on Ubuntu 18.04.2 LTS (docker://18.6.3)

I0520 10:39:37.455787       1 request.go:942] Request Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1beta1","metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/","verb":"get"},"user":"system:anonymous","group":["system:unauthenticated"]},"status":{"allowed":false}}
I0520 10:39:37.456347       1 round_trippers.go:419] curl -k -v -XPOST  -H "Content-Type: application/json" -H "User-Agent: image.app_linux-amd64.binary/v0.0.0 (linux/amd64) kubernetes/$Format" -H "Authorization: Bearer ###REDACTED###" -H "Accept: application/json, */*" 'https://10.96.0.1:443/apis/authorization.k8s.io/v1beta1/subjectaccessreviews'
I0520 10:39:37.460726       1 round_trippers.go:438] POST https://10.96.0.1:443/apis/authorization.k8s.io/v1beta1/subjectaccessreviews 201 Created in 4 milliseconds
I0520 10:39:37.460805       1 round_trippers.go:444] Response Headers:
I0520 10:39:37.460818       1 round_trippers.go:447]     Content-Type: application/json
I0520 10:39:37.460827       1 round_trippers.go:447]     Content-Length: 260
I0520 10:39:37.460837       1 round_trippers.go:447]     Date: Mon, 20 May 2019 10:39:37 GMT
I0520 10:39:37.460916       1 request.go:942] Response Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1beta1","metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/","verb":"get"},"user":"system:anonymous","group":["system:unauthenticated"]},"status":{"allowed":false}}
I0520 10:39:37.461163       1 authorization.go:73] Forbidden: "/", Reason: ""
I0520 10:39:37.461915       1 wrap.go:47] GET /: (6.880233ms) 403 [Go-http-client/2.0 192.168.178.192:3933]

Installation followed exactly https://docs.cert-manager.io/en/latest/getting-started/install.html#installing-with-helm and was installing in a new namespace (cert-manager).

spommerening on 20 May 2019

👍2

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.
If this issue is safe to close now please do so with /close.
Send feedback to jetstack.
/lifecycle stale

retest-bot on 18 Aug 2019

Stale issues rot after 30d of inactivity.
Mark the issue as fresh with /remove-lifecycle rotten.
Rotten issues close after an additional 30d of inactivity.
If this issue is safe to close now please do so with /close.
Send feedback to jetstack.
/lifecycle rotten
/remove-lifecycle stale

retest-bot on 17 Sep 2019

This has been addressed https://github.com/jetstack/cert-manager/pull/1527
/close

JoshVanL on 16 Oct 2019

@JoshVanL: Closing this issue.

In response to this:

This has been addressed https://github.com/jetstack/cert-manager/pull/1527
/close

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.