Context deadline exceeded during credential exchange about pinniped

[ankeesler]

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

[absoludity]

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.

[ankeesler]

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

[absoludity]

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

[absoludity]

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/[email protected]/pkg/server/httplog/httplog.go:237 +0xcf\nk8s.io/apiserver/pkg/server/httplog.(*respLogger).WriteHeader(0xc00067bd50, 0x1f4)\n\t/go/pkg/mod/k8s.io/[email protected]/pkg/server/httplog/httplog.go:216 +0x35\nk8s.io/apiserver/pkg/server/filters.(*baseTimeoutWriter).WriteHeader(0xc000387e00, 0x1f4)\n\t/go/pkg/mod/k8s.io/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/pkg/server/filters/timeout.go:113 +0xb8\ncreated by k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP\n\t/go/pkg/mod/k8s.io/[email protected]/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"

[enj]

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

[absoludity]

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/[email protected]/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/[email protected]/pkg/server/httplog/httplog.go:237 +0xcf\nk8s.io/apiserver/pkg/server/httplog.(*respLogger).WriteHeader(0xc000e244d0, 0x1f4)\n\t/go/pkg/mod/k8s.io/[email protected]/pkg/server/httplog/httplog.go:216 +0x35\nk8s.io/apiserver/pkg/server/filters.(*baseTimeoutWriter).WriteHeader(0xc000e1b0c0, 0x1f4)\n\t/go/pkg/mod/k8s.io/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/pkg/server/filters/timeout.go:113 +0xb8\ncreated by k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP\n\t/go/pkg/mod/k8s.io/[email protected]/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"

[mattmoyer]

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 kubernetes/kubernetes#95300, which I'm fairly confident is the bug we're observing.

The best thing for us may be to wait for kubernetes/kubernetes#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.

[mattmoyer]

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

[absoludity]

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