Closed absoludity closed 3 years ago
@absoludity - thanks for reporting. That is strange behavior indeed. Can you by chance tell where the timeout is coming from? I.e., is it coming from the client-side functionality, the TCP connection to the API server, the calling of the WebhookAuthenticator
, the response, etc? If I recall correctly, we should have a log statement printed when the aggregated API handles the TokenCredentialRequest
. On a successful request, you should see a log statement with "userID"
and "authenticated"
in it. Judging by your logs above, it looks like you are not seeing that? So perhaps the request is not even getting to the aggregated API...
My gut says that the issue here is not the 30 second timeout (I would hope that would be enough, although I have seen longer...), but rather something nefarious that is going on with the request that our client is making...
I just triggered it again - same thing, first time (cold) it timed out after 30s, then after that I did two successful ones which were much quicker. Checking the logs, I only see the successful requests:
I1112 22:07:09.334601 1 apiservice_updater.go:71] apiServiceUpdaterController Sync successfully updated API service
I1112 22:07:09.405904 1 webhookcachefiller.go:77] webhookcachefiller-controller "msg"="added new webhook authenticator" "endpoint"="https://local-user-authenticator.local-user-authenticator.svc/authenticate" "webhook"={"name":"local-user-authenticator","namespace":"pinniped-concierge"}
I1112 22:10:09.333346 1 certs_observer.go:66] certsObserverController Sync updated certs in the dynamic cert provider
I1112 22:10:09.333547 1 certs_expirer.go:88] certsExpirerController Sync found a renew delta of -415h34m23.666465361s
I1112 22:10:09.399173 1 apiservice_updater.go:71] apiServiceUpdaterController Sync successfully updated API service
I1112 22:10:09.802699 1 webhookcachefiller.go:77] webhookcachefiller-controller "msg"="added new webhook authenticator" "endpoint"="https://local-user-authenticator.local-user-authenticator.svc/authenticate" "webhook"={"name":"local-user-authenticator","namespace":"pinniped-concierge"}
I1112 22:10:43.594507 1 trace.go:205] Trace[375523728]: "create" kind: (12-Nov-2020 22:10:43.404) (total time: 190ms):
Trace[375523728]: ---"success" userID:81a93607-f5c2-4629-9ba7-5caaf67665e8,authenticated:true 190ms (22:10:00.594)
Trace[375523728]: [190.261351ms] [190.261351ms] END
I1112 22:10:53.100618 1 trace.go:205] Trace[1820159643]: "create" kind: (12-Nov-2020 22:10:53.003) (total time: 96ms):
Trace[1820159643]: ---"success" userID:81a93607-f5c2-4629-9ba7-5caaf67665e8,authenticated:true 96ms (22:10:00.100)
Trace[1820159643]: [96.918049ms] [96.918049ms] END
It's pretty reliable: if I wait for the creds to expire, then the next one will do the same 30s timeout. I'll try to dig deeper later today.
Thanks for trying again, and thanks for sending more logs. I tried to reproduce this on my machine, and did see a slightly longer roundtrip time for the first exchange-credential
call[0] as compared to the next series of calls[1]. Obviously this is not a perfect reproduction, but I do wonder if it points to the part of the system that is slow upon a credential update.
I currently have a test running that waits an hour for the credential (i.e., the returned certificate from the pinniped exchange-credential
call) to expire, and then reruns the pinniped exchange-credential
command. I am watching all logs of any Concierge pod, hoping that something isn't slipping by us because it is only happening in one pod.
So if we assume for a second that this timeout behavior happens after the credential times out, then that puzzles me, because in a pinniped exchange-credential
command, we don't even look at that credential, and I don't believe we have any caching on the server side either.
The hunt for an answer continues...
[0]
real 0m1.208s
user 0m0.011s
sys 0m0.009s
[1]
real 0m0.241s
user 0m0.011s
sys 0m0.008s
So I tried enabling pprof yesterday (seems to be enabled for the generic API already, but I added serverConfig.EnableProfiling = true
around here, built and ran with that image.
I didn't add the results as I didn't see anything interesting, but could have missed something (or not had it setup correctly). This is the pdf for the data during the 30s timeout:
and for the second request which returned within a second or so:
Both just show calls to metrics, but nothing that seems significant (at least to me).
Building from tip of main and running that image with the config map updated to show debug logs, I was able to reproduce with the following logged errors:
E1117 23:42:18.970213 1 webhook.go:199] Failed to make webhook authorizer request: context canceled
E1117 23:42:18.970471 1 errors.go:77] context canceled
I1117 23:42:19.467648 1 httplog.go:89] "HTTP" verb="POST" URI="/apis/login.concierge.pinniped.dev/v1alpha1/namespaces/pinniped-concierge/tokencredentialrequests" latency="46.079222673s" userAgent="pinniped/v0.2.0 (linux/amd64) kubernetes/1223cf7" srcIP="10.244.0.1:50000" resp=500 statusStack="\ngoroutine 14015 [running]:\nk8s.io/apiserver/pkg/server/httplog.(*respLogger).recordStatus(0xc00067bd50, 0x1f4)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/httplog/httplog.go:237 +0xcf\nk8s.io/apiserver/pkg/server/httplog.(*respLogger).WriteHeader(0xc00067bd50, 0x1f4)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/httplog/httplog.go:216 +0x35\nk8s.io/apiserver/pkg/server/filters.(*baseTimeoutWriter).WriteHeader(0xc000387e00, 0x1f4)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/filters/timeout.go:228 +0xb2\nnet/http.Error(0x7f5811d0f098, 0xc000604c60, 0xc0006fa2d0, 0x8c, 0x1f4)\n\t/usr/local/go/src/net/http/server.go:2054 +0x1f6\nk8s.io/apiserver/pkg/endpoints/handlers/responsewriters.InternalError(0x7f5811d0f098, 0xc000604c60, 0xc0009d2b00, 0x1fb9f80, 0xc000e84d00)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/endpoints/handlers/responsewriters/errors.go:75 +0x11e\nk8s.io/apiserver/pkg/endpoints/filters.WithAuthorization.func1(0x7f5811d0f098, 0xc000604c60, 0xc0009d2b00)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/endpoints/filters/authorization.go:69 +0x497\nnet/http.HandlerFunc.ServeHTTP(0xc000729940, 0x7f5811d0f098, 0xc000604c60, 0xc0009d2b00)\n\t/usr/local/go/src/net/http/server.go:2042 +0x44\nk8s.io/apiserver/pkg/server/filters.WithMaxInFlightLimit.func2(0x7f5811d0f098, 0xc000604c60, 0xc0009d2b00)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/filters/maxinflight.go:175 +0x4cf\nnet/http.HandlerFunc.ServeHTTP(0xc000870330, 0x7f5811d0f098, 0xc000604c60, 0xc0009d2b00)\n\t/usr/local/go/src/net/http/server.go:2042 +0x44\nk8s.io/apiserver/pkg/endpoints/filters.WithImpersonation.func1(0x7f5811d0f098, 0xc000604c60, 0xc0009d2b00)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/endpoints/filters/impersonation.go:50 +0x231d\nnet/http.HandlerFunc.ServeHTTP(0xc000729980, 0x7f5811d0f098, 0xc000604c60, 0xc0009d2b00)\n\t/usr/local/go/src/net/http/server.go:2042 +0x44\nk8s.io/apiserver/pkg/endpoints/filters.WithAuthentication.func1(0x7f5811d0f098, 0xc000604c60, 0xc0009d2a00)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/endpoints/filters/authentication.go:70 +0x672\nnet/http.HandlerFunc.ServeHTTP(0xc0006a6550, 0x7f5811d0f098, 0xc000604c60, 0xc0009d2a00)\n\t/usr/local/go/src/net/http/server.go:2042 +0x44\nk8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP.func1(0xc0008c1b60, 0xc000461640, 0x20043c0, 0xc000604c60, 0xc0009d2a00)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/filters/timeout.go:113 +0xb8\ncreated by k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/filters/timeout.go:99 +0x1cc\n" addedInfo="\nlogging error output: \"Internal Server Error: \\\"/apis/login.concierge.pinniped.dev/v1alpha1/namespaces/pinniped-concierge/tokencredentialrequests\\\": context canceled\\n\"\n"
Last line, cleaned up for readability:
I1117 23:42:19.467648 1 httplog.go:89]
"HTTP"
verb="POST"
URI="/apis/login.concierge.pinniped.dev/v1alpha1/namespaces/pinniped-concierge/tokencredentialrequests"
latency="46.079222673s"
userAgent="pinniped/v0.2.0 (linux/amd64) kubernetes/1223cf7"
srcIP="10.244.0.1:50000"
resp=500
statusStack=
running [Created by filters.(*timeoutHandler).ServeHTTP @ timeout.go:99]
httplog httplog.go:237 (*respLogger).recordStatus(*respLogger(#2), 500)
httplog httplog.go:216 (*respLogger).WriteHeader(*respLogger(#2), 500)
filters timeout.go:228 (*baseTimeoutWriter).WriteHeader(*baseTimeoutWriter(0xc000387e00), 500)
http server.go:2054 Error(ResponseWriter(#5), string(0xc0006fa2d0, len=140), 500)
responsewriters errors.go:75 InternalError(ResponseWriter(#5), *Request(#4), error(0x1fb9f80))
filters authorization.go:69 WithAuthorization.func1(Handler(#5), Authorizer(#4))
filters maxinflight.go:175 WithMaxInFlightLimit.func2(Handler(#5), 824644020992)
filters impersonation.go:50 WithImpersonation.func1(Handler(#5), Authorizer(#4))
filters authentication.go:70 WithAuthentication.func1(Handler(#5), Request(#3))
filters timeout.go:113 (*timeoutHandler).ServeHTTP.func1(0xc0008c1b60, 0xc000461640, 0x20043c0, #1, #3)
addedInfo=
logging error output:
Internal Server Error: "/apis/login.concierge.pinniped.dev/v1alpha1/namespaces/pinniped-concierge/tokencredentialrequests":
context canceled
I retried later in the day with logLevel=all
. The request was:
$ date -u && time PINNIPED_TOKEN=pinny-the-seal:password123 pinniped exchange-credential
Wed 18 Nov 2020 04:25:08 UTC
failed to get credential: could not login: Post "https://127.0.0.1:46863/apis/login.concierge.pinniped.dev/v1alpha1/namespaces/pinniped-concierge/tokencredentialrequests": context deadline exceeded
0.01s user 0.01s system 0% cpu 30.074 total
Note that the context deadline is at 30s as noted previously. The odd thing is that the relevant part of the actual logs is actually at 47s after the request. So the pinniped CLI is seeing one context deadline, while concierge appears to see a different (longer) one. Full logs during the time of the request through to the context deadline in concierge:
I1118 04:25:07.134094 1 handler.go:153] pinniped-concierge: GET "/openapi/v2" satisfied by nonGoRestful
I1118 04:25:07.134133 1 pathrecorder.go:253] pinniped-concierge: "/openapi/v2" satisfied by NotFoundHandler
I1118 04:25:07.134362 1 httplog.go:89] "HTTP" verb="GET" URI="/openapi/v2" latency="5.659753ms" userAgent="" srcIP="10.244.0.1:22068" resp=404
I1118 04:25:10.093467 1 request.go:1097] Request Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/apis/login.concierge.pinniped.dev/v1alpha1","verb":"get"},"user":"system:serviceaccount:kube-system:generic-garbage-collector","groups":["system:serviceaccounts","system:serviceaccounts:kube-system","system:authenticated"]},"status":{"allowed":false}}
I1118 04:25:10.093575 1 round_trippers.go:423] curl -k -v -XPOST -H "Accept: application/json, */*" -H "Content-Type: application/json" -H "User-Agent: pinniped-concierge/v0.0.0 (linux/amd64) kubernetes/$Format" -H "Authorization: Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6InV5enJNUFdDS2dENjdUU3p5Y1hxSjVPYlFDenBjY3NieHVqU0hlRDBWd1EifQ.eyJpc3MiOiJrdWJlcm5ldGVzL3NlcnZpY2VhY2NvdW50Iiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9uYW1lc3BhY2UiOiJwaW5uaXBlZC1jb25jaWVyZ2UiLCJrdWJlcm5ldGVzLmlvL3NlcnZpY2VhY2NvdW50L3NlY3JldC5uYW1lIjoicGlubmlwZWQtY29uY2llcmdlLXRva2VuLW0yOXRwIiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9zZXJ2aWNlLWFjY291bnQubmFtZSI6InBpbm5pcGVkLWNvbmNpZXJnZSIsImt1YmVybmV0ZXMuaW8vc2VydmljZWFjY291bnQvc2VydmljZS1hY2NvdW50LnVpZCI6IjRmYjUyODJiLTI3YzQtNGRhZi1iZDEwLWQzZjU2YTdlMzVlZiIsInN1YiI6InN5c3RlbTpzZXJ2aWNlYWNjb3VudDpwaW5uaXBlZC1jb25jaWVyZ2U6cGlubmlwZWQtY29uY2llcmdlIn0.gO7Cn-Z0W5eIbt08ZcjgzwuL5xkkV4oQ5s8YwnVo9Zu0ezxSlXV1Dz2bX5uXYY03gFt70nJ5WpbuxfLhwAaOMmiqqZhOIvvU4BgIVeHULXclY_1PDDlYPUT4z_9mtewuvzR1z03U2C31BMOdsJtXFqw4ggB0QvhjzkefswZPjTBfiPrHyBfnYoIMGDCsDzDS_7p45aZHsVvfu-v-Tmx1vd4diuZ86Kr521oRhkq3-0DuNZA9nT98dvvrEmREnE9FNtrpSyDXP9WicCUIKhI4p7VIQcyBhdlWVZneKfRkKU6X9gxtHTie0Nt9lcfYNAYFmSy_NLLFNm4Z1uK9oL51Gg" 'https://10.96.0.1:443/apis/authorization.k8s.io/v1/subjectaccessreviews'
I1118 04:25:10.094806 1 round_trippers.go:443] POST https://10.96.0.1:443/apis/authorization.k8s.io/v1/subjectaccessreviews 201 Created in 1 milliseconds
I1118 04:25:10.094826 1 round_trippers.go:449] Response Headers:
I1118 04:25:10.094832 1 round_trippers.go:452] Content-Type: application/json
I1118 04:25:10.094837 1 round_trippers.go:452] Content-Length: 812
I1118 04:25:10.094841 1 round_trippers.go:452] Date: Wed, 18 Nov 2020 04:25:10 GMT
I1118 04:25:10.094863 1 request.go:1097] Response Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null,"managedFields":[{"manager":"pinniped-concierge","operation":"Update","apiVersion":"authorization.k8s.io/v1","time":"2020-11-18T04:25:10Z","fieldsType":"FieldsV1","fieldsV1":{"f:spec":{"f:groups":{},"f:nonResourceAttributes":{".":{},"f:path":{},"f:verb":{}},"f:user":{}}}}]},"spec":{"nonResourceAttributes":{"path":"/apis/login.concierge.pinniped.dev/v1alpha1","verb":"get"},"user":"system:serviceaccount:kube-system:generic-garbage-collector","groups":["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\""}}
I1118 04:25:10.094983 1 handler.go:143] pinniped-concierge: GET "/apis/login.concierge.pinniped.dev/v1alpha1" satisfied by gorestful with webservice /apis/login.concierge.pinniped.dev/v1alpha1
I1118 04:25:10.095156 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/login.concierge.pinniped.dev/v1alpha1?timeout=32s" latency="63.634059ms" userAgent="kube-controller-manager/v1.18.2 (linux/amd64) kubernetes/52c56ce/system:serviceaccount:kube-system:generic-garbage-collector" srcIP="10.244.0.1:22068" resp=200
I1118 04:25:10.317196 1 reflector.go:515] pkg/mod/k8s.io/client-go@v0.19.2/tools/cache/reflector.go:156: Watch close - *v1.ValidatingWebhookConfiguration total 0 items received
I1118 04:25:10.317586 1 round_trippers.go:423] curl -k -v -XGET -H "Authorization: Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6InV5enJNUFdDS2dENjdUU3p5Y1hxSjVPYlFDenBjY3NieHVqU0hlRDBWd1EifQ.eyJpc3MiOiJrdWJlcm5ldGVzL3NlcnZpY2VhY2NvdW50Iiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9uYW1lc3BhY2UiOiJwaW5uaXBlZC1jb25jaWVyZ2UiLCJrdWJlcm5ldGVzLmlvL3NlcnZpY2VhY2NvdW50L3NlY3JldC5uYW1lIjoicGlubmlwZWQtY29uY2llcmdlLXRva2VuLW0yOXRwIiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9zZXJ2aWNlLWFjY291bnQubmFtZSI6InBpbm5pcGVkLWNvbmNpZXJnZSIsImt1YmVybmV0ZXMuaW8vc2VydmljZWFjY291bnQvc2VydmljZS1hY2NvdW50LnVpZCI6IjRmYjUyODJiLTI3YzQtNGRhZi1iZDEwLWQzZjU2YTdlMzVlZiIsInN1YiI6InN5c3RlbTpzZXJ2aWNlYWNjb3VudDpwaW5uaXBlZC1jb25jaWVyZ2U6cGlubmlwZWQtY29uY2llcmdlIn0.gO7Cn-Z0W5eIbt08ZcjgzwuL5xkkV4oQ5s8YwnVo9Zu0ezxSlXV1Dz2bX5uXYY03gFt70nJ5WpbuxfLhwAaOMmiqqZhOIvvU4BgIVeHULXclY_1PDDlYPUT4z_9mtewuvzR1z03U2C31BMOdsJtXFqw4ggB0QvhjzkefswZPjTBfiPrHyBfnYoIMGDCsDzDS_7p45aZHsVvfu-v-Tmx1vd4diuZ86Kr521oRhkq3-0DuNZA9nT98dvvrEmREnE9FNtrpSyDXP9WicCUIKhI4p7VIQcyBhdlWVZneKfRkKU6X9gxtHTie0Nt9lcfYNAYFmSy_NLLFNm4Z1uK9oL51Gg" -H "Accept: application/json, */*" -H "User-Agent: pinniped-concierge/v0.0.0 (linux/amd64) kubernetes/$Format" 'https://10.96.0.1:443/apis/admissionregistration.k8s.io/v1/validatingwebhookconfigurations?allowWatchBookmarks=true&resourceVersion=649&timeout=5m25s&timeoutSeconds=325&watch=true'
I1118 04:25:10.318873 1 round_trippers.go:443] GET https://10.96.0.1:443/apis/admissionregistration.k8s.io/v1/validatingwebhookconfigurations?allowWatchBookmarks=true&resourceVersion=649&timeout=5m25s&timeoutSeconds=325&watch=true 200 OK in 1 milliseconds
I1118 04:25:10.318925 1 round_trippers.go:449] Response Headers:
I1118 04:25:10.318942 1 round_trippers.go:452] Content-Type: application/json
I1118 04:25:10.318952 1 round_trippers.go:452] Date: Wed, 18 Nov 2020 04:25:10 GMT
I1118 04:25:11.793722 1 handler.go:153] pinniped-concierge: GET "/healthz" satisfied by nonGoRestful
I1118 04:25:11.889403 1 pathrecorder.go:240] pinniped-concierge: "/healthz" satisfied by exact match
I1118 04:25:11.889926 1 httplog.go:89] "HTTP" verb="GET" URI="/healthz" latency="100.174467ms" userAgent="kube-probe/1.18" srcIP="10.244.0.1:34552" resp=200
I1118 04:25:15.891596 1 request.go:1097] Request Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/healthz","verb":"get"},"user":"system:anonymous","groups":["system:unauthenticated"]},"status":{"allowed":false}}
I1118 04:25:15.891802 1 round_trippers.go:423] curl -k -v -XPOST -H "Content-Type: application/json" -H "User-Agent: pinniped-concierge/v0.0.0 (linux/amd64) kubernetes/$Format" -H "Authorization: Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6InV5enJNUFdDS2dENjdUU3p5Y1hxSjVPYlFDenBjY3NieHVqU0hlRDBWd1EifQ.eyJpc3MiOiJrdWJlcm5ldGVzL3NlcnZpY2VhY2NvdW50Iiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9uYW1lc3BhY2UiOiJwaW5uaXBlZC1jb25jaWVyZ2UiLCJrdWJlcm5ldGVzLmlvL3NlcnZpY2VhY2NvdW50L3NlY3JldC5uYW1lIjoicGlubmlwZWQtY29uY2llcmdlLXRva2VuLW0yOXRwIiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9zZXJ2aWNlLWFjY291bnQubmFtZSI6InBpbm5pcGVkLWNvbmNpZXJnZSIsImt1YmVybmV0ZXMuaW8vc2VydmljZWFjY291bnQvc2VydmljZS1hY2NvdW50LnVpZCI6IjRmYjUyODJiLTI3YzQtNGRhZi1iZDEwLWQzZjU2YTdlMzVlZiIsInN1YiI6InN5c3RlbTpzZXJ2aWNlYWNjb3VudDpwaW5uaXBlZC1jb25jaWVyZ2U6cGlubmlwZWQtY29uY2llcmdlIn0.gO7Cn-Z0W5eIbt08ZcjgzwuL5xkkV4oQ5s8YwnVo9Zu0ezxSlXV1Dz2bX5uXYY03gFt70nJ5WpbuxfLhwAaOMmiqqZhOIvvU4BgIVeHULXclY_1PDDlYPUT4z_9mtewuvzR1z03U2C31BMOdsJtXFqw4ggB0QvhjzkefswZPjTBfiPrHyBfnYoIMGDCsDzDS_7p45aZHsVvfu-v-Tmx1vd4diuZ86Kr521oRhkq3-0DuNZA9nT98dvvrEmREnE9FNtrpSyDXP9WicCUIKhI4p7VIQcyBhdlWVZneKfRkKU6X9gxtHTie0Nt9lcfYNAYFmSy_NLLFNm4Z1uK9oL51Gg" -H "Accept: application/json, */*" 'https://10.96.0.1:443/apis/authorization.k8s.io/v1/subjectaccessreviews'
I1118 04:25:15.895108 1 round_trippers.go:443] POST https://10.96.0.1:443/apis/authorization.k8s.io/v1/subjectaccessreviews 201 Created in 3 milliseconds
I1118 04:25:15.895162 1 round_trippers.go:449] Response Headers:
I1118 04:25:15.895175 1 round_trippers.go:452] Content-Type: application/json
I1118 04:25:15.895185 1 round_trippers.go:452] Content-Length: 694
I1118 04:25:15.895193 1 round_trippers.go:452] Date: Wed, 18 Nov 2020 04:25:15 GMT
I1118 04:25:15.895240 1 request.go:1097] Response Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null,"managedFields":[{"manager":"pinniped-concierge","operation":"Update","apiVersion":"authorization.k8s.io/v1","time":"2020-11-18T04:25:15Z","fieldsType":"FieldsV1","fieldsV1":{"f:spec":{"f:groups":{},"f:nonResourceAttributes":{".":{},"f:path":{},"f:verb":{}},"f:user":{}}}}]},"spec":{"nonResourceAttributes":{"path":"/healthz","verb":"get"},"user":"system:anonymous","groups":["system:unauthenticated"]},"status":{"allowed":true,"reason":"RBAC: allowed by ClusterRoleBinding \"system:public-info-viewer\" of ClusterRole \"system:public-info-viewer\" to Group \"system:unauthenticated\""}}
I1118 04:25:15.895491 1 handler.go:153] pinniped-concierge: GET "/healthz" satisfied by nonGoRestful
I1118 04:25:15.895538 1 pathrecorder.go:240] pinniped-concierge: "/healthz" satisfied by exact match
I1118 04:25:15.896405 1 httplog.go:89] "HTTP" verb="GET" URI="/healthz" latency="206.657916ms" userAgent="kube-probe/1.18" srcIP="10.244.0.1:34624" resp=200
I1118 04:25:22.089620 1 handler.go:153] pinniped-concierge: GET "/healthz" satisfied by nonGoRestful
I1118 04:25:22.089636 1 pathrecorder.go:240] pinniped-concierge: "/healthz" satisfied by exact match
I1118 04:25:22.089858 1 httplog.go:89] "HTTP" verb="GET" URI="/healthz" latency="300.138817ms" userAgent="kube-probe/1.18" srcIP="10.244.0.1:34726" resp=200
I1118 04:25:25.892015 1 handler.go:153] pinniped-concierge: GET "/healthz" satisfied by nonGoRestful
I1118 04:25:25.892067 1 pathrecorder.go:240] pinniped-concierge: "/healthz" satisfied by exact match
I1118 04:25:25.892816 1 httplog.go:89] "HTTP" verb="GET" URI="/healthz" latency="203.064076ms" userAgent="kube-probe/1.18" srcIP="10.244.0.1:34798" resp=200
I1118 04:25:27.636272 1 handler.go:143] pinniped-concierge: GET "/apis/login.concierge.pinniped.dev/v1alpha1" satisfied by gorestful with webservice /apis/login.concierge.pinniped.dev/v1alpha1
I1118 04:25:27.636392 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/login.concierge.pinniped.dev/v1alpha1?timeout=32s" latency="1.87833ms" userAgent="kubectl/v1.18.2 (linux/amd64) kubernetes/52c56ce" srcIP="10.244.0.1:22068" resp=200
I1118 04:25:31.992968 1 request.go:1097] Request Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/healthz","verb":"get"},"user":"system:anonymous","groups":["system:unauthenticated"]},"status":{"allowed":false}}
I1118 04:25:31.993247 1 round_trippers.go:423] curl -k -v -XPOST -H "Authorization: Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6InV5enJNUFdDS2dENjdUU3p5Y1hxSjVPYlFDenBjY3NieHVqU0hlRDBWd1EifQ.eyJpc3MiOiJrdWJlcm5ldGVzL3NlcnZpY2VhY2NvdW50Iiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9uYW1lc3BhY2UiOiJwaW5uaXBlZC1jb25jaWVyZ2UiLCJrdWJlcm5ldGVzLmlvL3NlcnZpY2VhY2NvdW50L3NlY3JldC5uYW1lIjoicGlubmlwZWQtY29uY2llcmdlLXRva2VuLW0yOXRwIiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9zZXJ2aWNlLWFjY291bnQubmFtZSI6InBpbm5pcGVkLWNvbmNpZXJnZSIsImt1YmVybmV0ZXMuaW8vc2VydmljZWFjY291bnQvc2VydmljZS1hY2NvdW50LnVpZCI6IjRmYjUyODJiLTI3YzQtNGRhZi1iZDEwLWQzZjU2YTdlMzVlZiIsInN1YiI6InN5c3RlbTpzZXJ2aWNlYWNjb3VudDpwaW5uaXBlZC1jb25jaWVyZ2U6cGlubmlwZWQtY29uY2llcmdlIn0.gO7Cn-Z0W5eIbt08ZcjgzwuL5xkkV4oQ5s8YwnVo9Zu0ezxSlXV1Dz2bX5uXYY03gFt70nJ5WpbuxfLhwAaOMmiqqZhOIvvU4BgIVeHULXclY_1PDDlYPUT4z_9mtewuvzR1z03U2C31BMOdsJtXFqw4ggB0QvhjzkefswZPjTBfiPrHyBfnYoIMGDCsDzDS_7p45aZHsVvfu-v-Tmx1vd4diuZ86Kr521oRhkq3-0DuNZA9nT98dvvrEmREnE9FNtrpSyDXP9WicCUIKhI4p7VIQcyBhdlWVZneKfRkKU6X9gxtHTie0Nt9lcfYNAYFmSy_NLLFNm4Z1uK9oL51Gg" -H "Accept: application/json, */*" -H "Content-Type: application/json" -H "User-Agent: pinniped-concierge/v0.0.0 (linux/amd64) kubernetes/$Format" 'https://10.96.0.1:443/apis/authorization.k8s.io/v1/subjectaccessreviews'
I1118 04:25:32.089359 1 round_trippers.go:443] POST https://10.96.0.1:443/apis/authorization.k8s.io/v1/subjectaccessreviews 201 Created in 96 milliseconds
I1118 04:25:32.089397 1 round_trippers.go:449] Response Headers:
I1118 04:25:32.089410 1 round_trippers.go:452] Content-Type: application/json
I1118 04:25:32.089420 1 round_trippers.go:452] Content-Length: 694
I1118 04:25:32.089429 1 round_trippers.go:452] Date: Wed, 18 Nov 2020 04:25:31 GMT
I1118 04:25:32.089463 1 request.go:1097] Response Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null,"managedFields":[{"manager":"pinniped-concierge","operation":"Update","apiVersion":"authorization.k8s.io/v1","time":"2020-11-18T04:25:31Z","fieldsType":"FieldsV1","fieldsV1":{"f:spec":{"f:groups":{},"f:nonResourceAttributes":{".":{},"f:path":{},"f:verb":{}},"f:user":{}}}}]},"spec":{"nonResourceAttributes":{"path":"/healthz","verb":"get"},"user":"system:anonymous","groups":["system:unauthenticated"]},"status":{"allowed":true,"reason":"RBAC: allowed by ClusterRoleBinding \"system:public-info-viewer\" of ClusterRole \"system:public-info-viewer\" to Group \"system:unauthenticated\""}}
I1118 04:25:32.089646 1 handler.go:153] pinniped-concierge: GET "/healthz" satisfied by nonGoRestful
I1118 04:25:32.089674 1 pathrecorder.go:240] pinniped-concierge: "/healthz" satisfied by exact match
I1118 04:25:32.090463 1 httplog.go:89] "HTTP" verb="GET" URI="/healthz" latency="297.817794ms" userAgent="kube-probe/1.18" srcIP="10.244.0.1:34908" resp=200
I1118 04:25:35.018752 1 request.go:1097] Request Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/apis/login.concierge.pinniped.dev/v1alpha1","verb":"get"},"user":"system:serviceaccount:kube-system:resourcequota-controller","groups":["system:serviceaccounts","system:serviceaccounts:kube-system","system:authenticated"]},"status":{"allowed":false}}
I1118 04:25:35.018799 1 round_trippers.go:423] curl -k -v -XPOST -H "Content-Type: application/json" -H "User-Agent: pinniped-concierge/v0.0.0 (linux/amd64) kubernetes/$Format" -H "Accept: application/json, */*" -H "Authorization: Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6InV5enJNUFdDS2dENjdUU3p5Y1hxSjVPYlFDenBjY3NieHVqU0hlRDBWd1EifQ.eyJpc3MiOiJrdWJlcm5ldGVzL3NlcnZpY2VhY2NvdW50Iiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9uYW1lc3BhY2UiOiJwaW5uaXBlZC1jb25jaWVyZ2UiLCJrdWJlcm5ldGVzLmlvL3NlcnZpY2VhY2NvdW50L3NlY3JldC5uYW1lIjoicGlubmlwZWQtY29uY2llcmdlLXRva2VuLW0yOXRwIiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9zZXJ2aWNlLWFjY291bnQubmFtZSI6InBpbm5pcGVkLWNvbmNpZXJnZSIsImt1YmVybmV0ZXMuaW8vc2VydmljZWFjY291bnQvc2VydmljZS1hY2NvdW50LnVpZCI6IjRmYjUyODJiLTI3YzQtNGRhZi1iZDEwLWQzZjU2YTdlMzVlZiIsInN1YiI6InN5c3RlbTpzZXJ2aWNlYWNjb3VudDpwaW5uaXBlZC1jb25jaWVyZ2U6cGlubmlwZWQtY29uY2llcmdlIn0.gO7Cn-Z0W5eIbt08ZcjgzwuL5xkkV4oQ5s8YwnVo9Zu0ezxSlXV1Dz2bX5uXYY03gFt70nJ5WpbuxfLhwAaOMmiqqZhOIvvU4BgIVeHULXclY_1PDDlYPUT4z_9mtewuvzR1z03U2C31BMOdsJtXFqw4ggB0QvhjzkefswZPjTBfiPrHyBfnYoIMGDCsDzDS_7p45aZHsVvfu-v-Tmx1vd4diuZ86Kr521oRhkq3-0DuNZA9nT98dvvrEmREnE9FNtrpSyDXP9WicCUIKhI4p7VIQcyBhdlWVZneKfRkKU6X9gxtHTie0Nt9lcfYNAYFmSy_NLLFNm4Z1uK9oL51Gg" 'https://10.96.0.1:443/apis/authorization.k8s.io/v1/subjectaccessreviews'
I1118 04:25:35.089263 1 round_trippers.go:443] POST https://10.96.0.1:443/apis/authorization.k8s.io/v1/subjectaccessreviews 201 Created in 70 milliseconds
I1118 04:25:35.089275 1 round_trippers.go:449] Response Headers:
I1118 04:25:35.089277 1 round_trippers.go:452] Content-Type: application/json
I1118 04:25:35.089279 1 round_trippers.go:452] Content-Length: 811
I1118 04:25:35.089281 1 round_trippers.go:452] Date: Wed, 18 Nov 2020 04:25:35 GMT
I1118 04:25:35.089317 1 request.go:1097] Response Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null,"managedFields":[{"manager":"pinniped-concierge","operation":"Update","apiVersion":"authorization.k8s.io/v1","time":"2020-11-18T04:25:35Z","fieldsType":"FieldsV1","fieldsV1":{"f:spec":{"f:groups":{},"f:nonResourceAttributes":{".":{},"f:path":{},"f:verb":{}},"f:user":{}}}}]},"spec":{"nonResourceAttributes":{"path":"/apis/login.concierge.pinniped.dev/v1alpha1","verb":"get"},"user":"system:serviceaccount:kube-system:resourcequota-controller","groups":["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\""}}
I1118 04:25:35.089449 1 handler.go:143] pinniped-concierge: GET "/apis/login.concierge.pinniped.dev/v1alpha1" satisfied by gorestful with webservice /apis/login.concierge.pinniped.dev/v1alpha1
I1118 04:25:35.089561 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/login.concierge.pinniped.dev/v1alpha1?timeout=32s" latency="72.3445ms" userAgent="kube-controller-manager/v1.18.2 (linux/amd64) kubernetes/52c56ce/system:serviceaccount:kube-system:resourcequota-controller" srcIP="10.244.0.1:22068" resp=200
I1118 04:25:35.692228 1 handler.go:153] pinniped-concierge: GET "/healthz" satisfied by nonGoRestful
I1118 04:25:35.692286 1 pathrecorder.go:240] pinniped-concierge: "/healthz" satisfied by exact match
I1118 04:25:35.692437 1 httplog.go:89] "HTTP" verb="GET" URI="/healthz" latency="2.732331ms" userAgent="kube-probe/1.18" srcIP="10.244.0.1:34982" resp=200
I1118 04:25:36.190228 1 handler.go:143] pinniped-concierge: GET "/apis/login.concierge.pinniped.dev/v1alpha1" satisfied by gorestful with webservice /apis/login.concierge.pinniped.dev/v1alpha1
I1118 04:25:36.190391 1 handler.go:143] pinniped-concierge: GET "/apis/login.concierge.pinniped.dev/v1alpha1" satisfied by gorestful with webservice /apis/login.concierge.pinniped.dev/v1alpha1
I1118 04:25:36.190506 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/login.concierge.pinniped.dev/v1alpha1" latency="754.504µs" userAgent="Go-http-client/2.0" srcIP="10.244.0.1:58878" resp=200
I1118 04:25:36.190658 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/login.concierge.pinniped.dev/v1alpha1" latency="831.762µs" userAgent="Go-http-client/2.0" srcIP="10.244.0.1:58878" resp=200
I1118 04:25:36.191843 1 handler.go:143] pinniped-concierge: GET "/apis/login.concierge.pinniped.dev/v1alpha1" satisfied by gorestful with webservice /apis/login.concierge.pinniped.dev/v1alpha1
I1118 04:25:36.192074 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/login.concierge.pinniped.dev/v1alpha1" latency="2.402979ms" userAgent="Go-http-client/2.0" srcIP="10.244.0.1:58878" resp=200
I1118 04:25:36.289693 1 handler.go:143] pinniped-concierge: GET "/apis/login.concierge.pinniped.dev/v1alpha1" satisfied by gorestful with webservice /apis/login.concierge.pinniped.dev/v1alpha1
I1118 04:25:36.389627 1 handler.go:143] pinniped-concierge: GET "/apis/login.concierge.pinniped.dev/v1alpha1" satisfied by gorestful with webservice /apis/login.concierge.pinniped.dev/v1alpha1
I1118 04:25:36.390006 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/login.concierge.pinniped.dev/v1alpha1" latency="200.35544ms" userAgent="Go-http-client/2.0" srcIP="10.244.0.1:58878" resp=200
I1118 04:25:36.489471 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/login.concierge.pinniped.dev/v1alpha1" latency="200.203416ms" userAgent="Go-http-client/2.0" srcIP="10.244.0.1:58878" resp=200
I1118 04:25:40.490221 1 request.go:1097] Request Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/apis/login.concierge.pinniped.dev/v1alpha1","verb":"get"},"user":"system:serviceaccount:kube-system:generic-garbage-collector","groups":["system:serviceaccounts","system:serviceaccounts:kube-system","system:authenticated"]},"status":{"allowed":false}}
I1118 04:25:40.490284 1 round_trippers.go:423] curl -k -v -XPOST -H "Content-Type: application/json" -H "Authorization: Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6InV5enJNUFdDS2dENjdUU3p5Y1hxSjVPYlFDenBjY3NieHVqU0hlRDBWd1EifQ.eyJpc3MiOiJrdWJlcm5ldGVzL3NlcnZpY2VhY2NvdW50Iiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9uYW1lc3BhY2UiOiJwaW5uaXBlZC1jb25jaWVyZ2UiLCJrdWJlcm5ldGVzLmlvL3NlcnZpY2VhY2NvdW50L3NlY3JldC5uYW1lIjoicGlubmlwZWQtY29uY2llcmdlLXRva2VuLW0yOXRwIiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9zZXJ2aWNlLWFjY291bnQubmFtZSI6InBpbm5pcGVkLWNvbmNpZXJnZSIsImt1YmVybmV0ZXMuaW8vc2VydmljZWFjY291bnQvc2VydmljZS1hY2NvdW50LnVpZCI6IjRmYjUyODJiLTI3YzQtNGRhZi1iZDEwLWQzZjU2YTdlMzVlZiIsInN1YiI6InN5c3RlbTpzZXJ2aWNlYWNjb3VudDpwaW5uaXBlZC1jb25jaWVyZ2U6cGlubmlwZWQtY29uY2llcmdlIn0.gO7Cn-Z0W5eIbt08ZcjgzwuL5xkkV4oQ5s8YwnVo9Zu0ezxSlXV1Dz2bX5uXYY03gFt70nJ5WpbuxfLhwAaOMmiqqZhOIvvU4BgIVeHULXclY_1PDDlYPUT4z_9mtewuvzR1z03U2C31BMOdsJtXFqw4ggB0QvhjzkefswZPjTBfiPrHyBfnYoIMGDCsDzDS_7p45aZHsVvfu-v-Tmx1vd4diuZ86Kr521oRhkq3-0DuNZA9nT98dvvrEmREnE9FNtrpSyDXP9WicCUIKhI4p7VIQcyBhdlWVZneKfRkKU6X9gxtHTie0Nt9lcfYNAYFmSy_NLLFNm4Z1uK9oL51Gg" -H "User-Agent: pinniped-concierge/v0.0.0 (linux/amd64) kubernetes/$Format" -H "Accept: application/json, */*" 'https://10.96.0.1:443/apis/authorization.k8s.io/v1/subjectaccessreviews'
I1118 04:25:40.491060 1 round_trippers.go:443] POST https://10.96.0.1:443/apis/authorization.k8s.io/v1/subjectaccessreviews 201 Created in 0 milliseconds
I1118 04:25:40.491070 1 round_trippers.go:449] Response Headers:
I1118 04:25:40.491073 1 round_trippers.go:452] Content-Type: application/json
I1118 04:25:40.491075 1 round_trippers.go:452] Content-Length: 812
I1118 04:25:40.491078 1 round_trippers.go:452] Date: Wed, 18 Nov 2020 04:25:40 GMT
I1118 04:25:40.491088 1 request.go:1097] Response Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null,"managedFields":[{"manager":"pinniped-concierge","operation":"Update","apiVersion":"authorization.k8s.io/v1","time":"2020-11-18T04:25:40Z","fieldsType":"FieldsV1","fieldsV1":{"f:spec":{"f:groups":{},"f:nonResourceAttributes":{".":{},"f:path":{},"f:verb":{}},"f:user":{}}}}]},"spec":{"nonResourceAttributes":{"path":"/apis/login.concierge.pinniped.dev/v1alpha1","verb":"get"},"user":"system:serviceaccount:kube-system:generic-garbage-collector","groups":["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\""}}
I1118 04:25:40.491155 1 handler.go:143] pinniped-concierge: GET "/apis/login.concierge.pinniped.dev/v1alpha1" satisfied by gorestful with webservice /apis/login.concierge.pinniped.dev/v1alpha1
I1118 04:25:40.491445 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/login.concierge.pinniped.dev/v1alpha1?timeout=32s" latency="302.820921ms" userAgent="kube-controller-manager/v1.18.2 (linux/amd64) kubernetes/52c56ce/system:serviceaccount:kube-system:generic-garbage-collector" srcIP="10.244.0.1:22068" resp=200
I1118 04:25:41.989637 1 handler.go:153] pinniped-concierge: GET "/healthz" satisfied by nonGoRestful
I1118 04:25:41.989698 1 pathrecorder.go:240] pinniped-concierge: "/healthz" satisfied by exact match
I1118 04:25:42.090126 1 httplog.go:89] "HTTP" verb="GET" URI="/healthz" latency="200.659743ms" userAgent="kube-probe/1.18" srcIP="10.244.0.1:35094" resp=200
I1118 04:25:45.672233 1 request.go:1097] Request Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/healthz","verb":"get"},"user":"system:anonymous","groups":["system:unauthenticated"]},"status":{"allowed":false}}
I1118 04:25:45.672304 1 round_trippers.go:423] curl -k -v -XPOST -H "Accept: application/json, */*" -H "Content-Type: application/json" -H "User-Agent: pinniped-concierge/v0.0.0 (linux/amd64) kubernetes/$Format" -H "Authorization: Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6InV5enJNUFdDS2dENjdUU3p5Y1hxSjVPYlFDenBjY3NieHVqU0hlRDBWd1EifQ.eyJpc3MiOiJrdWJlcm5ldGVzL3NlcnZpY2VhY2NvdW50Iiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9uYW1lc3BhY2UiOiJwaW5uaXBlZC1jb25jaWVyZ2UiLCJrdWJlcm5ldGVzLmlvL3NlcnZpY2VhY2NvdW50L3NlY3JldC5uYW1lIjoicGlubmlwZWQtY29uY2llcmdlLXRva2VuLW0yOXRwIiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9zZXJ2aWNlLWFjY291bnQubmFtZSI6InBpbm5pcGVkLWNvbmNpZXJnZSIsImt1YmVybmV0ZXMuaW8vc2VydmljZWFjY291bnQvc2VydmljZS1hY2NvdW50LnVpZCI6IjRmYjUyODJiLTI3YzQtNGRhZi1iZDEwLWQzZjU2YTdlMzVlZiIsInN1YiI6InN5c3RlbTpzZXJ2aWNlYWNjb3VudDpwaW5uaXBlZC1jb25jaWVyZ2U6cGlubmlwZWQtY29uY2llcmdlIn0.gO7Cn-Z0W5eIbt08ZcjgzwuL5xkkV4oQ5s8YwnVo9Zu0ezxSlXV1Dz2bX5uXYY03gFt70nJ5WpbuxfLhwAaOMmiqqZhOIvvU4BgIVeHULXclY_1PDDlYPUT4z_9mtewuvzR1z03U2C31BMOdsJtXFqw4ggB0QvhjzkefswZPjTBfiPrHyBfnYoIMGDCsDzDS_7p45aZHsVvfu-v-Tmx1vd4diuZ86Kr521oRhkq3-0DuNZA9nT98dvvrEmREnE9FNtrpSyDXP9WicCUIKhI4p7VIQcyBhdlWVZneKfRkKU6X9gxtHTie0Nt9lcfYNAYFmSy_NLLFNm4Z1uK9oL51Gg" 'https://10.96.0.1:443/apis/authorization.k8s.io/v1/subjectaccessreviews'
I1118 04:25:45.673307 1 round_trippers.go:443] POST https://10.96.0.1:443/apis/authorization.k8s.io/v1/subjectaccessreviews 201 Created in 0 milliseconds
I1118 04:25:45.673318 1 round_trippers.go:449] Response Headers:
I1118 04:25:45.673321 1 round_trippers.go:452] Content-Length: 694
I1118 04:25:45.673325 1 round_trippers.go:452] Date: Wed, 18 Nov 2020 04:25:45 GMT
I1118 04:25:45.673344 1 round_trippers.go:452] Content-Type: application/json
I1118 04:25:45.673384 1 request.go:1097] Response Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null,"managedFields":[{"manager":"pinniped-concierge","operation":"Update","apiVersion":"authorization.k8s.io/v1","time":"2020-11-18T04:25:45Z","fieldsType":"FieldsV1","fieldsV1":{"f:spec":{"f:groups":{},"f:nonResourceAttributes":{".":{},"f:path":{},"f:verb":{}},"f:user":{}}}}]},"spec":{"nonResourceAttributes":{"path":"/healthz","verb":"get"},"user":"system:anonymous","groups":["system:unauthenticated"]},"status":{"allowed":true,"reason":"RBAC: allowed by ClusterRoleBinding \"system:public-info-viewer\" of ClusterRole \"system:public-info-viewer\" to Group \"system:unauthenticated\""}}
I1118 04:25:45.673461 1 handler.go:153] pinniped-concierge: GET "/healthz" satisfied by nonGoRestful
I1118 04:25:45.673471 1 pathrecorder.go:240] pinniped-concierge: "/healthz" satisfied by exact match
I1118 04:25:45.673513 1 httplog.go:89] "HTTP" verb="GET" URI="/healthz" latency="3.004879ms" userAgent="kube-probe/1.18" srcIP="10.244.0.1:35166" resp=200
I1118 04:25:51.992612 1 handler.go:153] pinniped-concierge: GET "/healthz" satisfied by nonGoRestful
I1118 04:25:51.992659 1 pathrecorder.go:240] pinniped-concierge: "/healthz" satisfied by exact match
I1118 04:25:51.993218 1 httplog.go:89] "HTTP" verb="GET" URI="/healthz" latency="203.551736ms" userAgent="kube-probe/1.18" srcIP="10.244.0.1:35280" resp=200
I1118 04:25:55.792619 1 request.go:1097] Request Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/healthz","verb":"get"},"user":"system:anonymous","groups":["system:unauthenticated"]},"status":{"allowed":false}}
I1118 04:25:55.792734 1 round_trippers.go:423] curl -k -v -XPOST -H "Accept: application/json, */*" -H "Content-Type: application/json" -H "User-Agent: pinniped-concierge/v0.0.0 (linux/amd64) kubernetes/$Format" -H "Authorization: Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6InV5enJNUFdDS2dENjdUU3p5Y1hxSjVPYlFDenBjY3NieHVqU0hlRDBWd1EifQ.eyJpc3MiOiJrdWJlcm5ldGVzL3NlcnZpY2VhY2NvdW50Iiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9uYW1lc3BhY2UiOiJwaW5uaXBlZC1jb25jaWVyZ2UiLCJrdWJlcm5ldGVzLmlvL3NlcnZpY2VhY2NvdW50L3NlY3JldC5uYW1lIjoicGlubmlwZWQtY29uY2llcmdlLXRva2VuLW0yOXRwIiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9zZXJ2aWNlLWFjY291bnQubmFtZSI6InBpbm5pcGVkLWNvbmNpZXJnZSIsImt1YmVybmV0ZXMuaW8vc2VydmljZWFjY291bnQvc2VydmljZS1hY2NvdW50LnVpZCI6IjRmYjUyODJiLTI3YzQtNGRhZi1iZDEwLWQzZjU2YTdlMzVlZiIsInN1YiI6InN5c3RlbTpzZXJ2aWNlYWNjb3VudDpwaW5uaXBlZC1jb25jaWVyZ2U6cGlubmlwZWQtY29uY2llcmdlIn0.gO7Cn-Z0W5eIbt08ZcjgzwuL5xkkV4oQ5s8YwnVo9Zu0ezxSlXV1Dz2bX5uXYY03gFt70nJ5WpbuxfLhwAaOMmiqqZhOIvvU4BgIVeHULXclY_1PDDlYPUT4z_9mtewuvzR1z03U2C31BMOdsJtXFqw4ggB0QvhjzkefswZPjTBfiPrHyBfnYoIMGDCsDzDS_7p45aZHsVvfu-v-Tmx1vd4diuZ86Kr521oRhkq3-0DuNZA9nT98dvvrEmREnE9FNtrpSyDXP9WicCUIKhI4p7VIQcyBhdlWVZneKfRkKU6X9gxtHTie0Nt9lcfYNAYFmSy_NLLFNm4Z1uK9oL51Gg" 'https://10.96.0.1:443/apis/authorization.k8s.io/v1/subjectaccessreviews'
I1118 04:25:55.794420 1 round_trippers.go:443] POST https://10.96.0.1:443/apis/authorization.k8s.io/v1/subjectaccessreviews 201 Created in 1 milliseconds
I1118 04:25:55.794443 1 round_trippers.go:449] Response Headers:
I1118 04:25:55.794448 1 round_trippers.go:452] Content-Type: application/json
I1118 04:25:55.794452 1 round_trippers.go:452] Content-Length: 694
I1118 04:25:55.794456 1 round_trippers.go:452] Date: Wed, 18 Nov 2020 04:25:55 GMT
I1118 04:25:55.794473 1 request.go:1097] Response Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null,"managedFields":[{"manager":"pinniped-concierge","operation":"Update","apiVersion":"authorization.k8s.io/v1","time":"2020-11-18T04:25:55Z","fieldsType":"FieldsV1","fieldsV1":{"f:spec":{"f:groups":{},"f:nonResourceAttributes":{".":{},"f:path":{},"f:verb":{}},"f:user":{}}}}]},"spec":{"nonResourceAttributes":{"path":"/healthz","verb":"get"},"user":"system:anonymous","groups":["system:unauthenticated"]},"status":{"allowed":true,"reason":"RBAC: allowed by ClusterRoleBinding \"system:public-info-viewer\" of ClusterRole \"system:public-info-viewer\" to Group \"system:unauthenticated\""}}
I1118 04:25:55.794574 1 handler.go:153] pinniped-concierge: GET "/healthz" satisfied by nonGoRestful
I1118 04:25:55.794588 1 pathrecorder.go:240] pinniped-concierge: "/healthz" satisfied by exact match
I1118 04:25:55.794742 1 httplog.go:89] "HTTP" verb="GET" URI="/healthz" latency="105.084201ms" userAgent="kube-probe/1.18" srcIP="10.244.0.1:35356" resp=200
I1118 04:25:56.391193 1 request.go:1097] Request Body: {"kind":"SubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null},"spec":{"resourceAttributes":{"namespace":"pinniped-concierge","verb":"create","group":"login.concierge.pinniped.dev","version":"v1alpha1","resource":"tokencredentialrequests"},"user":"system:anonymous","groups":["system:unauthenticated"]},"status":{"allowed":false}}
E1118 04:25:56.391221 1 webhook.go:199] Failed to make webhook authorizer request: context canceled
E1118 04:25:56.392498 1 errors.go:77] context canceled
I1118 04:25:56.691251 1 httplog.go:89] "HTTP" verb="POST" URI="/apis/login.concierge.pinniped.dev/v1alpha1/namespaces/pinniped-concierge/tokencredentialrequests" latency="47.70927719s" userAgent="pinniped/v0.2.0 (linux/amd64) kubernetes/1223cf7" srcIP="10.244.0.1:22068" resp=500 statusStack="\ngoroutine 12964 [running]:\nk8s.io/apiserver/pkg/server/httplog.(*respLogger).recordStatus(0xc000e244d0, 0x1f4)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/httplog/httplog.go:237 +0xcf\nk8s.io/apiserver/pkg/server/httplog.(*respLogger).WriteHeader(0xc000e244d0, 0x1f4)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/httplog/httplog.go:216 +0x35\nk8s.io/apiserver/pkg/server/filters.(*baseTimeoutWriter).WriteHeader(0xc000e1b0c0, 0x1f4)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/filters/timeout.go:228 +0xb2\nnet/http.Error(0x7f192b393058, 0xc00061ce28, 0xc0004ec360, 0x8c, 0x1f4)\n\t/usr/local/go/src/net/http/server.go:2054 +0x1f6\nk8s.io/apiserver/pkg/endpoints/handlers/responsewriters.InternalError(0x7f192b393058, 0xc00061ce28, 0xc000bb3100, 0x1fb9f80, 0xc000982b80)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/endpoints/handlers/responsewriters/errors.go:75 +0x11e\nk8s.io/apiserver/pkg/endpoints/filters.WithAuthorization.func1(0x7f192b393058, 0xc00061ce28, 0xc000bb3100)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/endpoints/filters/authorization.go:69 +0x497\nnet/http.HandlerFunc.ServeHTTP(0xc000726600, 0x7f192b393058, 0xc00061ce28, 0xc000bb3100)\n\t/usr/local/go/src/net/http/server.go:2042 +0x44\nk8s.io/apiserver/pkg/server/filters.WithMaxInFlightLimit.func2(0x7f192b393058, 0xc00061ce28, 0xc000bb3100)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/filters/maxinflight.go:175 +0x4cf\nnet/http.HandlerFunc.ServeHTTP(0xc00057bad0, 0x7f192b393058, 0xc00061ce28, 0xc000bb3100)\n\t/usr/local/go/src/net/http/server.go:2042 +0x44\nk8s.io/apiserver/pkg/endpoints/filters.WithImpersonation.func1(0x7f192b393058, 0xc00061ce28, 0xc000bb3100)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/endpoints/filters/impersonation.go:50 +0x231d\nnet/http.HandlerFunc.ServeHTTP(0xc000726640, 0x7f192b393058, 0xc00061ce28, 0xc000bb3100)\n\t/usr/local/go/src/net/http/server.go:2042 +0x44\nk8s.io/apiserver/pkg/endpoints/filters.WithAuthentication.func1(0x7f192b393058, 0xc00061ce28, 0xc000bb2f00)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/endpoints/filters/authentication.go:70 +0x672\nnet/http.HandlerFunc.ServeHTTP(0xc00012bf40, 0x7f192b393058, 0xc00061ce28, 0xc000bb2f00)\n\t/usr/local/go/src/net/http/server.go:2042 +0x44\nk8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP.func1(0xc00074a420, 0xc000396ec0, 0x20043c0, 0xc00061ce28, 0xc000bb2f00)\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/filters/timeout.go:113 +0xb8\ncreated by k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP\n\t/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/filters/timeout.go:99 +0x1cc\n" addedInfo="\nlogging error output: \"Internal Server Error: \\\"/apis/login.concierge.pinniped.dev/v1alpha1/namespaces/pinniped-concierge/tokencredentialrequests\\\": context canceled\\n\"\n"
After a fair amount of profiling and tracing, I was able to identity some metrics-related code that was taking an unusually long time on these slow requests compared to a normal, fast request. This led me to https://github.com/kubernetes/kubernetes/issues/95300, which I'm fairly confident is the bug we're observing.
The best thing for us may be to wait for https://github.com/kubernetes/kubernetes/pull/96282 to land (backporting the fix to 1.19.x). We also have the option of running our own goroutine to keep the metrics from getting stale, like they do in that fix.
@absoludity I believe this is now fixed. I was able to install locally, let things sit idle for around an hour, and my next login was fast (~100ms). Please let me know if you notice otherwise.
I'm going to go ahead and mark this closed. We should follow up later to remove the workaround introduced in #233 once the upstream fix lands in a release.
Thanks @mattmoyer . Confirmed, I built a new image and tried again after leaving the computer for a couple of hours:
date -u && time PINNIPED_NAMESPACE=pinniped-concierge PINNIPED_AUTHENTICATOR_TYPE=webhook PINNIPED_AUTHENTICATOR_NAME=local-user-authenticator PINNIPED_CA_BUNDLE="$(cat /tmp/pinniped-k8s-ca-bundle-decoded)" PINNIPED_K8S_API_ENDPOINT=https://127.0.0.1:45021 PINNIPED_TOKEN=pinny-the-seal:password123 pinniped exchange-credential
Sun 22 Nov 2020 21:50:17 UTC
{"kind":"ExecCredential","apiVersion":"client.authentication.k8s.io/v1beta1","spec":{},"status":{"expirationTimestamp":"2020-11-22T21:55:17Z","clientCertificateData":"-----BEGIN CERTIFICATE-----\n...\n-----END CERTIFICATE-----\n","clientKeyData":"-----BEGIN PRIVATE KEY-----\n...\n-----END PRIVATE KEY-----\n"}}
0.02s user 0.01s system 25% cpu 0.097 total
I'm consistently seeing a context deadline of 30s exceeded when exchanging credentials the first time followed by successful responses taking 6-7 seconds afterwards.
What did you expect to happen?
I expected a cold request to be much quicker than the 30s deadline (and guess by the deadline that it's not meant to take so long?). Let me know if this is known and expected, or if it's not reproducible and is just my local kind cluster.
The request to exchange-credentials returns within a second, preferably much less.
What is the simplest way to reproduce this behavior?
As outlined above, call
pinniped exchange-credential
explicitly.In what environment did you see this bug?
Pinniped server version: 0.2.0
Pinniped client version: 0.2.0
Pinniped container image (if using a public container image): docker.io/getpinniped/pinniped-server:v0.2.0
Pinniped configuration (what IDP(s) are you using? what downstream credential minting mechanisms are you using?): See above env vars for exchange-credential .
Kubernetes version (use
kubectl version
): ``` Client Version: version.Info{Major:"1", Minor:"18", GitVersion:"v1.18.2", GitCommit:"52c56ce7a8272c798dbc29846288d7cd9fbae032", GitTreeState:"clean", BuildDate:"2020-04-16T11:56:40Z", GoVersion:"go1.13.9", Compiler:"gc", Platform:"linux/amd64"} Server Version: version.Info{Major:"1", Minor:"18", GitVersion:"v1.18.2", GitCommit:"52c56ce7a8272c798dbc29846288d7cd9fbae032", GitTreeState:"clean", BuildDate:"2020-04-30T20:19:45Z", GoVersion:"go1.13.9", Compiler:"gc", Platform:"linux/amd64"}Kubernetes installer & version (e.g.,
kubeadm version
): kind v0.8.0 go1.14.2 linux/amd64Cloud provider or hardware configuration: Dell Precision 5540
OS (e.g:
cat /etc/os-release
):Kernel (e.g.
uname -a
): Linux hpmor4 5.4.0-52-generic #57-Ubuntu SMP Thu Oct 15 10:57:00 UTC 2020 x86_64 x86_64 x86_64 GNU/LinuxOthers:
What else is there to know about this bug?
Also, I don't see anything relevant in the pinniped-concierge logs: