Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

High rate of error log messages in webhook #1479

Closed
donbowman opened this issue Mar 15, 2019 · 9 comments
Closed

High rate of error log messages in webhook #1479

donbowman opened this issue Mar 15, 2019 · 9 comments
Labels
kind/bug Categorizes issue or PR as related to a bug. lifecycle/rotten Denotes an issue or PR that has aged beyond stale and will be auto-closed.

Comments

@donbowman
Copy link

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
@jetstack-bot jetstack-bot added the kind/bug Categorizes issue or PR as related to a bug. label Mar 15, 2019
@dehypnosis
Copy link

dehypnosis commented Mar 19, 2019 •
edited

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?

@gak10100
Copy link

Same issue here w/ GKE

@dperetti
Copy link

😨

@str1k3r
Copy link

str1k3r commented Apr 26, 2019 •
edited

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

@dehypnosis dehypnosis mentioned this issue May 3, 2019
Open
@spommerening
Copy link

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).

@retest-bot
Copy link

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

@jetstack-bot jetstack-bot added the lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. label Aug 18, 2019
@retest-bot
Copy link

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

@jetstack-bot jetstack-bot added lifecycle/rotten Denotes an issue or PR that has aged beyond stale and will be auto-closed. and removed lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. labels Sep 17, 2019
@JoshVanL
Copy link
Contributor

This has been addressed #1527
/close

@jetstack-bot
Copy link
Contributor

@JoshVanL: Closing this issue.

In response to this:

This has been addressed #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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
kind/bug Categorizes issue or PR as related to a bug. lifecycle/rotten Denotes an issue or PR that has aged beyond stale and will be auto-closed.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
9 participants
@str1k3r @dperetti @gak10100 @dehypnosis @spommerening @donbowman @JoshVanL @jetstack-bot @retest-bot