Authentication service issue

[maps1995]

Describe the bug

I have multiple OKD clusters, recently I had a problem with authentication service of my clusters, authentication cluster operator has been degraded repeatedly, I've checked the logs and found it seems the problem is on openshift-oauth-apiserver, pods restart every couple hours repeatedly, I've checked the logs and found error related to the etcd, but when I've checked the etcd status, everything was ok. I don't know what is the actual problem.

One of openshift-oauth-apiserver pods log:

Defaulted container "oauth-apiserver" out of: oauth-apiserver, fix-audit-permissions (init)
I1225 23:03:15.369334       1 flags.go:64] FLAG: --accesstoken-inactivity-timeout="0s"
I1225 23:03:15.369871       1 flags.go:64] FLAG: --add-dir-header="false"
I1225 23:03:15.369983       1 flags.go:64] FLAG: --admission-control-config-file=""
I1225 23:03:15.370036       1 flags.go:64] FLAG: --advertise-address="<nil>"
I1225 23:03:15.370088       1 flags.go:64] FLAG: --alsologtostderr="false"
I1225 23:03:15.370129       1 flags.go:64] FLAG: --api-audiences="[https://kubernetes.default.svc]"
I1225 23:03:15.370179       1 flags.go:64] FLAG: --audit-log-batch-buffer-size="10000"
I1225 23:03:15.370221       1 flags.go:64] FLAG: --audit-log-batch-max-size="1"
I1225 23:03:15.370259       1 flags.go:64] FLAG: --audit-log-batch-max-wait="0s"
I1225 23:03:15.370299       1 flags.go:64] FLAG: --audit-log-batch-throttle-burst="0"
I1225 23:03:15.370336       1 flags.go:64] FLAG: --audit-log-batch-throttle-enable="false"
I1225 23:03:15.370378       1 flags.go:64] FLAG: --audit-log-batch-throttle-qps="0"
I1225 23:03:15.370423       1 flags.go:64] FLAG: --audit-log-compress="false"
I1225 23:03:15.370463       1 flags.go:64] FLAG: --audit-log-format="json"
I1225 23:03:15.370501       1 flags.go:64] FLAG: --audit-log-maxage="0"
I1225 23:03:15.370537       1 flags.go:64] FLAG: --audit-log-maxbackup="10"
I1225 23:03:15.370573       1 flags.go:64] FLAG: --audit-log-maxsize="100"
I1225 23:03:15.370610       1 flags.go:64] FLAG: --audit-log-mode="blocking"
I1225 23:03:15.370647       1 flags.go:64] FLAG: --audit-log-path="/var/log/oauth-apiserver/audit.log"
I1225 23:03:15.370685       1 flags.go:64] FLAG: --audit-log-truncate-enabled="false"
I1225 23:03:15.370724       1 flags.go:64] FLAG: --audit-log-truncate-max-batch-size="10485760"
I1225 23:03:15.370767       1 flags.go:64] FLAG: --audit-log-truncate-max-event-size="102400"
I1225 23:03:15.370804       1 flags.go:64] FLAG: --audit-log-version="audit.k8s.io/v1"
I1225 23:03:15.370841       1 flags.go:64] FLAG: --audit-policy-file="/var/run/configmaps/audit/policy.yaml"
I1225 23:03:15.370898       1 flags.go:64] FLAG: --audit-webhook-batch-buffer-size="10000"
I1225 23:03:15.370952       1 flags.go:64] FLAG: --audit-webhook-batch-initial-backoff="10s"
I1225 23:03:15.370993       1 flags.go:64] FLAG: --audit-webhook-batch-max-size="400"
I1225 23:03:15.371031       1 flags.go:64] FLAG: --audit-webhook-batch-max-wait="30s"
I1225 23:03:15.371068       1 flags.go:64] FLAG: --audit-webhook-batch-throttle-burst="15"
I1225 23:03:15.371104       1 flags.go:64] FLAG: --audit-webhook-batch-throttle-enable="true"
I1225 23:03:15.371141       1 flags.go:64] FLAG: --audit-webhook-batch-throttle-qps="10"
I1225 23:03:15.371180       1 flags.go:64] FLAG: --audit-webhook-config-file=""
I1225 23:03:15.371240       1 flags.go:64] FLAG: --audit-webhook-initial-backoff="10s"
I1225 23:03:15.371283       1 flags.go:64] FLAG: --audit-webhook-mode="batch"
I1225 23:03:15.371321       1 flags.go:64] FLAG: --audit-webhook-truncate-enabled="false"
I1225 23:03:15.371360       1 flags.go:64] FLAG: --audit-webhook-truncate-max-batch-size="10485760"
I1225 23:03:15.371398       1 flags.go:64] FLAG: --audit-webhook-truncate-max-event-size="102400"
I1225 23:03:15.371435       1 flags.go:64] FLAG: --audit-webhook-version="audit.k8s.io/v1"
I1225 23:03:15.371472       1 flags.go:64] FLAG: --authentication-kubeconfig=""
I1225 23:03:15.371509       1 flags.go:64] FLAG: --authentication-skip-lookup="false"
I1225 23:03:15.371546       1 flags.go:64] FLAG: --authentication-token-webhook-cache-ttl="10s"
I1225 23:03:15.371583       1 flags.go:64] FLAG: --authentication-tolerate-lookup-failure="false"
I1225 23:03:15.371619       1 flags.go:64] FLAG: --authorization-always-allow-paths="[/healthz,/readyz,/livez]"
I1225 23:03:15.371669       1 flags.go:64] FLAG: --authorization-kubeconfig=""
I1225 23:03:15.371706       1 flags.go:64] FLAG: --authorization-webhook-cache-authorized-ttl="10s"
I1225 23:03:15.371745       1 flags.go:64] FLAG: --authorization-webhook-cache-unauthorized-ttl="10s"
I1225 23:03:15.371784       1 flags.go:64] FLAG: --bind-address="0.0.0.0"
I1225 23:03:15.371823       1 flags.go:64] FLAG: --cert-dir="apiserver.local.config/certificates"
I1225 23:03:15.371861       1 flags.go:64] FLAG: --client-ca-file=""
I1225 23:03:15.371931       1 flags.go:64] FLAG: --contention-profiling="false"
I1225 23:03:15.371990       1 flags.go:64] FLAG: --cors-allowed-origins="[//127\\.0\\.0\\.1(:|$),//localhost(:|$)]"
I1225 23:03:15.372042       1 flags.go:64] FLAG: --default-watch-cache-size="100"
I1225 23:03:15.372081       1 flags.go:64] FLAG: --delete-collection-workers="1"
I1225 23:03:15.372118       1 flags.go:64] FLAG: --disable-admission-plugins="[]"
I1225 23:03:15.372162       1 flags.go:64] FLAG: --egress-selector-config-file=""
I1225 23:03:15.372199       1 flags.go:64] FLAG: --enable-admission-plugins="[]"
I1225 23:03:15.372239       1 flags.go:64] FLAG: --enable-garbage-collector="true"
I1225 23:03:15.372381       1 flags.go:64] FLAG: --enable-priority-and-fairness="true"
I1225 23:03:15.372505       1 flags.go:64] FLAG: --encryption-provider-config=""
I1225 23:03:15.372561       1 flags.go:64] FLAG: --etcd-cafile="/var/run/configmaps/etcd-serving-ca/ca-bundle.crt"
I1225 23:03:15.372602       1 flags.go:64] FLAG: --etcd-certfile="/var/run/secrets/etcd-client/tls.crt"
I1225 23:03:15.372639       1 flags.go:64] FLAG: --etcd-compaction-interval="5m0s"
I1225 23:03:15.372694       1 flags.go:64] FLAG: --etcd-count-metric-poll-period="1m0s"
I1225 23:03:15.372735       1 flags.go:64] FLAG: --etcd-db-metric-poll-interval="30s"
I1225 23:03:15.372771       1 flags.go:64] FLAG: --etcd-healthcheck-timeout="10s"
I1225 23:03:15.372808       1 flags.go:64] FLAG: --etcd-keyfile="/var/run/secrets/etcd-client/tls.key"
I1225 23:03:15.372845       1 flags.go:64] FLAG: --etcd-prefix="openshift.io"
I1225 23:03:15.372911       1 flags.go:64] FLAG: --etcd-servers="[https://192.168.102.71:2379,https://192.168.102.72:2379,https://192.168.102.73:2379]"
I1225 23:03:15.372985       1 flags.go:64] FLAG: --etcd-servers-overrides="[]"
I1225 23:03:15.373028       1 flags.go:64] FLAG: --external-hostname=""
I1225 23:03:15.373064       1 flags.go:64] FLAG: --feature-gates=""
I1225 23:03:15.373109       1 flags.go:64] FLAG: --goaway-chance="0"
I1225 23:03:15.373152       1 flags.go:64] FLAG: --help="false"
I1225 23:03:15.373189       1 flags.go:64] FLAG: --http2-max-streams-per-connection="1000"
I1225 23:03:15.373226       1 flags.go:64] FLAG: --kubeconfig=""
I1225 23:03:15.373262       1 flags.go:64] FLAG: --lease-reuse-duration-seconds="60"
I1225 23:03:15.373299       1 flags.go:64] FLAG: --livez-grace-period="0s"
I1225 23:03:15.373336       1 flags.go:64] FLAG: --log-backtrace-at=":0"
I1225 23:03:15.373378       1 flags.go:64] FLAG: --log-dir=""
I1225 23:03:15.373415       1 flags.go:64] FLAG: --log-file=""
I1225 23:03:15.373450       1 flags.go:64] FLAG: --log-file-max-size="1800"
I1225 23:03:15.373487       1 flags.go:64] FLAG: --log-flush-frequency="5s"
I1225 23:03:15.373524       1 flags.go:64] FLAG: --logtostderr="true"
I1225 23:03:15.373565       1 flags.go:64] FLAG: --master-service-namespace="default"
I1225 23:03:15.373663       1 flags.go:64] FLAG: --max-mutating-requests-inflight="200"
I1225 23:03:15.373707       1 flags.go:64] FLAG: --max-requests-inflight="400"
I1225 23:03:15.373744       1 flags.go:64] FLAG: --min-request-timeout="1800"
I1225 23:03:15.373781       1 flags.go:64] FLAG: --one-output="false"
I1225 23:03:15.373817       1 flags.go:64] FLAG: --permit-address-sharing="false"
I1225 23:03:15.373853       1 flags.go:64] FLAG: --permit-port-sharing="false"
I1225 23:03:15.373918       1 flags.go:64] FLAG: --profiling="true"
I1225 23:03:15.373989       1 flags.go:64] FLAG: --request-timeout="1m0s"
I1225 23:03:15.374032       1 flags.go:64] FLAG: --requestheader-allowed-names="[]"
I1225 23:03:15.374078       1 flags.go:64] FLAG: --requestheader-client-ca-file=""
I1225 23:03:15.374115       1 flags.go:64] FLAG: --requestheader-extra-headers-prefix="[x-remote-extra-]"
I1225 23:03:15.374171       1 flags.go:64] FLAG: --requestheader-group-headers="[x-remote-group]"
I1225 23:03:15.374218       1 flags.go:64] FLAG: --requestheader-username-headers="[x-remote-user]"
I1225 23:03:15.374259       1 flags.go:64] FLAG: --secure-port="8443"
I1225 23:03:15.374296       1 flags.go:64] FLAG: --shutdown-delay-duration="15s"
I1225 23:03:15.374332       1 flags.go:64] FLAG: --shutdown-send-retry-after="false"
I1225 23:03:15.374369       1 flags.go:64] FLAG: --skip-headers="false"
I1225 23:03:15.374406       1 flags.go:64] FLAG: --skip-log-headers="false"
I1225 23:03:15.374441       1 flags.go:64] FLAG: --stderrthreshold="2"
I1225 23:03:15.374477       1 flags.go:64] FLAG: --storage-backend=""
I1225 23:03:15.374514       1 flags.go:64] FLAG: --storage-media-type="application/json"
I1225 23:03:15.374551       1 flags.go:64] FLAG: --strict-transport-security-directives="[]"
I1225 23:03:15.374593       1 flags.go:64] FLAG: --tls-cert-file="/var/run/secrets/serving-cert/tls.crt"
I1225 23:03:15.374631       1 flags.go:64] FLAG: --tls-cipher-suites="[TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256,TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256]"
I1225 23:03:15.374689       1 flags.go:64] FLAG: --tls-min-version="VersionTLS12"
I1225 23:03:15.374728       1 flags.go:64] FLAG: --tls-private-key-file="/var/run/secrets/serving-cert/tls.key"
I1225 23:03:15.374766       1 flags.go:64] FLAG: --tls-sni-cert-key="[]"
I1225 23:03:15.374896       1 flags.go:64] FLAG: --tracing-config-file=""
I1225 23:03:15.374952       1 flags.go:64] FLAG: --v="2"
I1225 23:03:15.375013       1 flags.go:64] FLAG: --vmodule=""
I1225 23:03:15.375053       1 flags.go:64] FLAG: --watch-cache="true"
I1225 23:03:15.375090       1 flags.go:64] FLAG: --watch-cache-sizes="[]"
I1225 23:03:15.377561       1 dynamic_serving_content.go:113] "Loaded a new cert/key pair" name="serving-cert::/var/run/secrets/serving-cert/tls.crt::/var/run/secrets/serving-cert/tls.key"
I1225 23:03:17.782215       1 requestheader_controller.go:244] Loaded a new request header values for RequestHeaderAuthRequestController
I1225 23:03:17.784395       1 audit.go:349] Using audit backend: ignoreErrors<log>
I1225 23:03:17.787109       1 plugins.go:158] Loaded 2 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,MutatingAdmissionWebhook.
I1225 23:03:17.787228       1 plugins.go:161] Loaded 1 validating admission controller(s) successfully in the following order: ValidatingAdmissionWebhook.
I1225 23:03:17.787741       1 apf_controller.go:218] NewTestableController "Controller" with serverConcurrencyLimit=600, requestWaitLimit=15s, name=Controller, asFieldManager="api-priority-and-fairness-config-consumer-v1"
I1225 23:03:17.903006       1 store.go:1452] "Monitoring resource count at path" resource="oauthclients.oauth.openshift.io" path="<storage-prefix>//oauth/clients"
I1225 23:03:17.964704       1 cacher.go:410] cacher (*oauth.OAuthClient): initialized
I1225 23:03:17.968684       1 store.go:1452] "Monitoring resource count at path" resource="oauthauthorizetokens.oauth.openshift.io" path="<storage-prefix>//oauth/authorizetokens"
I1225 23:03:18.007145       1 store.go:1452] "Monitoring resource count at path" resource="oauthaccesstokens.oauth.openshift.io" path="<storage-prefix>//oauth/accesstokens"
I1225 23:03:18.016759       1 cacher.go:410] cacher (*oauth.OAuthAuthorizeToken): initialized
I1225 23:03:18.076266       1 store.go:1452] "Monitoring resource count at path" resource="oauthclientauthorizations.oauth.openshift.io" path="<storage-prefix>//oauth/clientauthorizations"
I1225 23:03:18.092607       1 cacher.go:410] cacher (*oauth.OAuthClientAuthorization): initialized
I1225 23:03:18.285705       1 cacher.go:410] cacher (*oauth.OAuthAccessToken): initialized
I1225 23:03:18.311447       1 store.go:1452] "Monitoring resource count at path" resource="users.user.openshift.io" path="<storage-prefix>//users"
I1225 23:03:18.322400       1 cacher.go:410] cacher (*user.User): initialized
I1225 23:03:18.323230       1 store.go:1452] "Monitoring resource count at path" resource="identities.user.openshift.io" path="<storage-prefix>//useridentities"
I1225 23:03:18.340503       1 store.go:1452] "Monitoring resource count at path" resource="groups.user.openshift.io" path="<storage-prefix>//groups"
I1225 23:03:18.349508       1 cacher.go:410] cacher (*user.Identity): initialized
I1225 23:03:18.371717       1 cacher.go:410] cacher (*user.Group): initialized
I1225 23:03:19.184336       1 aggregator.go:115] Building initial OpenAPI spec
I1225 23:03:19.190539       1 aggregator.go:118] Finished initial OpenAPI spec generation after 6.149197ms
I1225 23:03:19.191270       1 genericapiserver.go:418] MuxAndDiscoveryComplete has all endpoints registered and discovery information is complete
I1225 23:03:19.202680       1 tlsconfig.go:200] "Loaded serving cert" certName="serving-cert::/var/run/secrets/serving-cert/tls.crt::/var/run/secrets/serving-cert/tls.key" certDetail="\"api.openshift-oauth-apiserver.svc\" [serving] validServingFor=[api.openshift-oauth-apiserver.svc,api.openshift-oauth-apiserver.svc.cluster.local] issuer=\"openshift-service-serving-signer@1692003371\" (2023-08-14 08:57:46 +0000 UTC to 2025-08-13 08:57:47 +0000 UTC (now=2023-12-25 23:03:19.202610088 +0000 UTC))"
I1225 23:03:19.203153       1 named_certificates.go:53] "Loaded SNI cert" index=0 certName="self-signed loopback" certDetail="\"apiserver-loopback-client@1703545397\" [serving] validServingFor=[apiserver-loopback-client] issuer=\"apiserver-loopback-client-ca@1703545396\" (2023-12-25 22:03:15 +0000 UTC to 2024-12-24 22:03:15 +0000 UTC (now=2023-12-25 23:03:19.203104709 +0000 UTC))"
I1225 23:03:19.203477       1 secure_serving.go:210] Serving securely on [::]:8443
I1225 23:03:19.203668       1 genericapiserver.go:488] [graceful-termination] waiting for shutdown to be initiated
I1225 23:03:19.203815       1 requestheader_controller.go:169] Starting RequestHeaderAuthRequestController
I1225 23:03:19.203925       1 shared_informer.go:255] Waiting for caches to sync for RequestHeaderAuthRequestController
I1225 23:03:19.204440       1 dynamic_serving_content.go:132] "Starting controller" name="serving-cert::/var/run/secrets/serving-cert/tls.crt::/var/run/secrets/serving-cert/tls.key"
I1225 23:03:19.206283       1 configmap_cafile_content.go:202] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"
I1225 23:03:19.207501       1 shared_informer.go:255] Waiting for caches to sync for client-ca::kube-system::extension-apiserver-authentication::client-ca-file
I1225 23:03:19.207662       1 configmap_cafile_content.go:202] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"
I1225 23:03:19.207754       1 shared_informer.go:255] Waiting for caches to sync for client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file
I1225 23:03:19.212225       1 tlsconfig.go:240] "Starting DynamicServingCertificateController"
I1225 23:03:19.235478       1 apf_controller.go:317] Starting API Priority and Fairness config controller
I1225 23:03:19.327678       1 shared_informer.go:262] Caches are synced for client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file
I1225 23:03:19.333278       1 shared_informer.go:262] Caches are synced for RequestHeaderAuthRequestController
I1225 23:03:19.336013       1 shared_informer.go:262] Caches are synced for client-ca::kube-system::extension-apiserver-authentication::client-ca-file
I1225 23:03:19.341655       1 tlsconfig.go:178] "Loaded client CA" index=0 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"openshift-kube-apiserver-operator_aggregator-client-signer@1701141301\" [] issuer=\"<self>\" (2023-11-28 03:15:01 +0000 UTC to 2023-12-28 03:15:02 +0000 UTC (now=2023-12-25 23:03:19.341576343 +0000 UTC))"
I1225 23:03:19.342208       1 tlsconfig.go:178] "Loaded client CA" index=1 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"openshift-kube-apiserver-operator_aggregator-client-signer@1702437301\" [] issuer=\"<self>\" (2023-12-13 03:15:00 +0000 UTC to 2024-01-12 03:15:01 +0000 UTC (now=2023-12-25 23:03:19.341850246 +0000 UTC))"
I1225 23:03:19.344192       1 tlsconfig.go:200] "Loaded serving cert" certName="serving-cert::/var/run/secrets/serving-cert/tls.crt::/var/run/secrets/serving-cert/tls.key" certDetail="\"api.openshift-oauth-apiserver.svc\" [serving] validServingFor=[api.openshift-oauth-apiserver.svc,api.openshift-oauth-apiserver.svc.cluster.local] issuer=\"openshift-service-serving-signer@1692003371\" (2023-08-14 08:57:46 +0000 UTC to 2025-08-13 08:57:47 +0000 UTC (now=2023-12-25 23:03:19.343655347 +0000 UTC))"
I1225 23:03:19.345498       1 named_certificates.go:53] "Loaded SNI cert" index=0 certName="self-signed loopback" certDetail="\"apiserver-loopback-client@1703545397\" [serving] validServingFor=[apiserver-loopback-client] issuer=\"apiserver-loopback-client-ca@1703545396\" (2023-12-25 22:03:15 +0000 UTC to 2024-12-24 22:03:15 +0000 UTC (now=2023-12-25 23:03:19.345445327 +0000 UTC))"
I1225 23:03:19.355811       1 tlsconfig.go:178] "Loaded client CA" index=0 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"admin-kubeconfig-signer\" [] issuer=\"<self>\" (2023-08-14 08:02:22 +0000 UTC to 2033-08-11 08:02:22 +0000 UTC (now=2023-12-25 23:03:19.355750403 +0000 UTC))"
I1225 23:03:19.382367       1 tlsconfig.go:178] "Loaded client CA" index=1 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"kube-control-plane-signer\" [] issuer=\"<self>\" (2023-08-14 08:02:27 +0000 UTC to 2024-08-13 08:02:27 +0000 UTC (now=2023-12-25 23:03:19.382260061 +0000 UTC))"
I1225 23:03:19.382456       1 tlsconfig.go:178] "Loaded client CA" index=2 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"kube-apiserver-to-kubelet-signer\" [] issuer=\"<self>\" (2023-08-14 08:02:27 +0000 UTC to 2024-08-13 08:02:27 +0000 UTC (now=2023-12-25 23:03:19.382418824 +0000 UTC))"
I1225 23:03:19.382517       1 tlsconfig.go:178] "Loaded client CA" index=3 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"kubelet-bootstrap-kubeconfig-signer\" [] issuer=\"<self>\" (2023-08-14 08:02:24 +0000 UTC to 2033-08-11 08:02:24 +0000 UTC (now=2023-12-25 23:03:19.382475499 +0000 UTC))"
I1225 23:03:19.382569       1 tlsconfig.go:178] "Loaded client CA" index=4 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"openshift-kube-apiserver-operator_node-system-admin-signer@1692003365\" [] issuer=\"<self>\" (2023-08-14 08:56:04 +0000 UTC to 2024-08-13 08:56:05 +0000 UTC (now=2023-12-25 23:03:19.38253362 +0000 UTC))"
I1225 23:03:19.382619       1 tlsconfig.go:178] "Loaded client CA" index=5 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"openshift-kube-apiserver-operator_kube-control-plane-signer@1699776170\" [] issuer=\"<self>\" (2023-11-12 08:02:50 +0000 UTC to 2024-01-11 08:02:51 +0000 UTC (now=2023-12-25 23:03:19.382586871 +0000 UTC))"
I1225 23:03:19.382675       1 tlsconfig.go:178] "Loaded client CA" index=6 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"openshift-kube-controller-manager-operator_csr-signer-signer@1699845287\" [] issuer=\"<self>\" (2023-11-13 03:14:46 +0000 UTC to 2024-01-12 03:14:47 +0000 UTC (now=2023-12-25 23:03:19.382640133 +0000 UTC))"
I1225 23:03:19.382726       1 tlsconfig.go:178] "Loaded client CA" index=7 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"kube-csr-signer_@1701270904\" [] issuer=\"openshift-kube-controller-manager-operator_csr-signer-signer@1699845287\" (2023-11-29 15:15:03 +0000 UTC to 2023-12-29 15:15:04 +0000 UTC (now=2023-12-25 23:03:19.382691055 +0000 UTC))"
I1225 23:03:19.382782       1 tlsconfig.go:178] "Loaded client CA" index=8 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"openshift-kube-apiserver-operator_kube-control-plane-signer@1702368192\" [] issuer=\"<self>\" (2023-12-12 08:03:12 +0000 UTC to 2024-02-10 08:03:13 +0000 UTC (now=2023-12-25 23:03:19.382743762 +0000 UTC))"
I1225 23:03:19.382840       1 tlsconfig.go:178] "Loaded client CA" index=9 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"openshift-kube-apiserver-operator_kube-control-plane-signer@1702368192\" [] issuer=\"<self>\" (2023-12-12 08:03:12 +0000 UTC to 2024-02-10 08:03:13 +0000 UTC (now=2023-12-25 23:03:19.382806679 +0000 UTC))"
I1225 23:03:19.382980       1 tlsconfig.go:178] "Loaded client CA" index=10 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"openshift-kube-controller-manager-operator_csr-signer-signer@1702437286\" [] issuer=\"<self>\" (2023-12-13 03:14:45 +0000 UTC to 2024-02-11 03:14:46 +0000 UTC (now=2023-12-25 23:03:19.382876486 +0000 UTC))"
I1225 23:03:19.383068       1 tlsconfig.go:178] "Loaded client CA" index=11 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"kube-csr-signer_@1702566905\" [] issuer=\"openshift-kube-controller-manager-operator_csr-signer-signer@1702437286\" (2023-12-14 15:15:04 +0000 UTC to 2024-01-13 15:15:05 +0000 UTC (now=2023-12-25 23:03:19.383020912 +0000 UTC))"
I1225 23:03:19.383119       1 tlsconfig.go:178] "Loaded client CA" index=12 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"openshift-kube-apiserver-operator_aggregator-client-signer@1701141301\" [] issuer=\"<self>\" (2023-11-28 03:15:01 +0000 UTC to 2023-12-28 03:15:02 +0000 UTC (now=2023-12-25 23:03:19.383086081 +0000 UTC))"
I1225 23:03:19.383168       1 tlsconfig.go:178] "Loaded client CA" index=13 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"openshift-kube-apiserver-operator_aggregator-client-signer@1702437301\" [] issuer=\"<self>\" (2023-12-13 03:15:00 +0000 UTC to 2024-01-12 03:15:01 +0000 UTC (now=2023-12-25 23:03:19.383135315 +0000 UTC))"
I1225 23:03:19.383533       1 tlsconfig.go:200] "Loaded serving cert" certName="serving-cert::/var/run/secrets/serving-cert/tls.crt::/var/run/secrets/serving-cert/tls.key" certDetail="\"api.openshift-oauth-apiserver.svc\" [serving] validServingFor=[api.openshift-oauth-apiserver.svc,api.openshift-oauth-apiserver.svc.cluster.local] issuer=\"openshift-service-serving-signer@1692003371\" (2023-08-14 08:57:46 +0000 UTC to 2025-08-13 08:57:47 +0000 UTC (now=2023-12-25 23:03:19.383490695 +0000 UTC))"
I1225 23:03:19.383942       1 named_certificates.go:53] "Loaded SNI cert" index=0 certName="self-signed loopback" certDetail="\"apiserver-loopback-client@1703545397\" [serving] validServingFor=[apiserver-loopback-client] issuer=\"apiserver-loopback-client-ca@1703545396\" (2023-12-25 22:03:15 +0000 UTC to 2024-12-24 22:03:15 +0000 UTC (now=2023-12-25 23:03:19.383768643 +0000 UTC))"
I1225 23:03:19.437117       1 apf_controller.go:322] Running API Priority and Fairness config worker
E1226 00:00:24.870401       1 timeout.go:141] post-timeout activity - time-elapsed: 4.244640682s, GET "/readyz" result: <nil>
E1226 00:00:26.906955       1 timeout.go:141] post-timeout activity - time-elapsed: 5.277741193s, GET "/readyz" result: <nil>
E1226 00:00:27.943483       1 timeout.go:141] post-timeout activity - time-elapsed: 2.30578235s, GET "/readyz" result: <nil>
E1226 00:00:31.544789       1 timeout.go:141] post-timeout activity - time-elapsed: 918.43456ms, GET "/healthz" result: <nil>
I1226 00:00:31.547242       1 trace.go:205] Trace[1388597448]: "Get" url:/apis/oauth.openshift.io/v1/oauthclients/console,user-agent:console/v0.0.0 (linux/amd64) kubernetes/$Format,audit-id:e12f95aa-a497-43fa-a8d2-31bc961059bc,client:192.168.102.73,accept:application/vnd.kubernetes.protobuf,application/json,protocol:HTTP/2.0 (26-Dec-2023 00:00:29.437) (total time: 2109ms):
Trace[1388597448]: ---"About to write a response" 2109ms (00:00:31.547)
Trace[1388597448]: [2.109253227s] [2.109253227s] END
E1226 00:00:31.846329       1 timeout.go:141] post-timeout activity - time-elapsed: 1.219141959s, GET "/readyz" result: <nil>
I1226 00:00:33.723231       1 trace.go:205] Trace[1067034176]: "Get" url:/apis/oauth.openshift.io/v1/oauthclients/console,user-agent:console/v0.0.0 (linux/amd64) kubernetes/$Format,audit-id:92a4a632-6b81-4485-990f-30b0caa7fb9c,client:192.168.102.73,accept:application/vnd.kubernetes.protobuf,application/json,protocol:HTTP/2.0 (26-Dec-2023 00:00:33.166) (total time: 556ms):
Trace[1067034176]: ---"About to write a response" 556ms (00:00:33.723)
Trace[1067034176]: [556.791434ms] [556.791434ms] END
I1226 00:00:34.410733       1 trace.go:205] Trace[1016321966]: "Get" url:/apis/oauth.openshift.io/v1/oauthclients/console,user-agent:console/v0.0.0 (linux/amd64) kubernetes/$Format,audit-id:a1e5dc6e-644b-4c01-9b68-8e2f510df0fb,client:192.168.102.73,accept:application/vnd.kubernetes.protobuf,application/json,protocol:HTTP/2.0 (26-Dec-2023 00:00:33.746) (total time: 664ms):
Trace[1016321966]: ---"About to write a response" 664ms (00:00:34.410)
Trace[1016321966]: [664.525406ms] [664.525406ms] END
I1226 00:26:52.892645       1 trace.go:205] Trace[503145309]: "Get" url:/apis/oauth.openshift.io/v1/oauthaccesstokens/sha256~HAyvzrigtcDirFG0T-TByRyegaDqfVErQ3a04XStmvU,user-agent:Go-http-client/2.0,audit-id:ec293cbd-ef3a-4a87-87d3-56f6b0bc1b53,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 00:26:52.100) (total time: 792ms):
Trace[503145309]: ---"About to write a response" 792ms (00:26:52.892)
Trace[503145309]: [792.348531ms] [792.348531ms] END
I1226 00:26:53.228595       1 trace.go:205] Trace[755111229]: "Create" url:/apis/oauth.openshift.io/v1/tokenreviews,user-agent:Go-http-client/2.0,audit-id:03f5e32e-4a5d-49d2-9889-5007aa5aee69,client:100.64.0.4,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 00:26:52.097) (total time: 1130ms):
Trace[755111229]: ---"Object stored in database" 1130ms (00:26:53.228)
Trace[755111229]: [1.130665777s] [1.130665777s] END
I1226 00:27:25.241431       1 trace.go:205] Trace[1843311865]: "Get" url:/apis/oauth.openshift.io/v1/oauthclients/console,user-agent:console/v0.0.0 (linux/amd64) kubernetes/$Format,audit-id:6f068c1f-c2a9-46bc-9ec1-c3a9ba4d5c28,client:192.168.102.73,accept:application/vnd.kubernetes.protobuf,application/json,protocol:HTTP/2.0 (26-Dec-2023 00:27:24.492) (total time: 749ms):
Trace[1843311865]: ---"About to write a response" 749ms (00:27:25.241)
Trace[1843311865]: [749.330929ms] [749.330929ms] END
E1226 00:30:46.603822       1 timeout.go:141] post-timeout activity - time-elapsed: 978.696973ms, GET "/readyz" result: <nil>
E1226 00:31:11.389256       1 timeout.go:141] post-timeout activity - time-elapsed: 758.818839ms, GET "/healthz" result: <nil>
E1226 00:31:40.660773       1 timeout.go:141] post-timeout activity - time-elapsed: 34.576297ms, GET "/healthz" result: <nil>
E1226 00:38:51.218180       1 timeout.go:141] post-timeout activity - time-elapsed: 591.771121ms, GET "/readyz" result: <nil>
E1226 00:38:51.631314       1 timeout.go:141] post-timeout activity - time-elapsed: 2.432102ms, GET "/readyz" result: <nil>
E1226 00:44:30.741110       1 timeout.go:141] post-timeout activity - time-elapsed: 115.49169ms, GET "/readyz" result: <nil>
E1226 00:44:30.741478       1 timeout.go:141] post-timeout activity - time-elapsed: 115.951264ms, GET "/healthz" result: <nil>
I1226 00:44:53.548302       1 trace.go:205] Trace[508703698]: "Get" url:/apis/oauth.openshift.io/v1/oauthaccesstokens/sha256~HAyvzrigtcDirFG0T-TByRyegaDqfVErQ3a04XStmvU,user-agent:Go-http-client/2.0,audit-id:14f0409c-b933-47a5-8464-daf040dfebb4,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 00:44:52.768) (total time: 779ms):
Trace[508703698]: ---"About to write a response" 779ms (00:44:53.547)
Trace[508703698]: [779.588747ms] [779.588747ms] END
I1226 00:44:53.591736       1 trace.go:205] Trace[1817284887]: "Create" url:/apis/oauth.openshift.io/v1/tokenreviews,user-agent:Go-http-client/2.0,audit-id:e54fc847-409c-4983-b303-9fac5ab3deaf,client:100.64.0.3,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 00:44:52.765) (total time: 826ms):
Trace[1817284887]: ---"Object stored in database" 825ms (00:44:53.591)
Trace[1817284887]: [826.464205ms] [826.464205ms] END
I1226 00:45:33.350185       1 trace.go:205] Trace[2089265636]: "Get" url:/apis/oauth.openshift.io/v1/oauthaccesstokens/sha256~jjABER-m_8p9DDjmJSGwVDOaPB_3hpKMPoBlATc_ytU,user-agent:Go-http-client/2.0,audit-id:c9ae1844-bbfa-49da-b499-dbc4ad33ad92,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 00:45:32.107) (total time: 1242ms):
Trace[2089265636]: ---"About to write a response" 1242ms (00:45:33.349)
Trace[2089265636]: [1.242764975s] [1.242764975s] END
I1226 00:45:34.458697       1 trace.go:205] Trace[797366316]: "Get" url:/apis/user.openshift.io/v1/users/admin,user-agent:Go-http-client/2.0,audit-id:cd5133bf-2283-4ee8-a28d-5cc60689a621,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 00:45:33.353) (total time: 1104ms):
Trace[797366316]: ---"About to write a response" 1104ms (00:45:34.458)
Trace[797366316]: [1.104931959s] [1.104931959s] END
I1226 00:45:34.458801       1 trace.go:205] Trace[567862687]: "Get" url:/apis/oauth.openshift.io/v1/oauthclients/console,user-agent:console/v0.0.0 (linux/amd64) kubernetes/$Format,audit-id:4cf6c5f4-edde-48a4-96b7-bacf6984987b,client:192.168.102.73,accept:application/vnd.kubernetes.protobuf,application/json,protocol:HTTP/2.0 (26-Dec-2023 00:45:33.465) (total time: 992ms):
Trace[567862687]: ---"About to write a response" 992ms (00:45:34.458)
Trace[567862687]: [992.763931ms] [992.763931ms] END
I1226 00:45:34.466713       1 trace.go:205] Trace[1852083204]: "Create" url:/apis/oauth.openshift.io/v1/tokenreviews,user-agent:Go-http-client/2.0,audit-id:36bea31b-8a99-43bb-b4c8-6ba23dd0c6f2,client:100.64.0.4,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 00:45:32.101) (total time: 2365ms):
Trace[1852083204]: ---"Object stored in database" 2364ms (00:45:34.466)
Trace[1852083204]: [2.365006385s] [2.365006385s] END
E1226 00:45:35.994570       1 timeout.go:141] post-timeout activity - time-elapsed: 367.101371ms, GET "/readyz" result: <nil>
E1226 00:46:15.812427       1 timeout.go:141] post-timeout activity - time-elapsed: 187.031503ms, GET "/readyz" result: <nil>
I1226 00:46:16.798282       1 trace.go:205] Trace[345626216]: "Get" url:/apis/oauth.openshift.io/v1/oauthaccesstokens/sha256~HAyvzrigtcDirFG0T-TByRyegaDqfVErQ3a04XStmvU,user-agent:Go-http-client/2.0,audit-id:abfa3ecf-87e9-419e-bf8a-11d8b49c1e70,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 00:46:16.173) (total time: 624ms):
Trace[345626216]: ---"About to write a response" 624ms (00:46:16.798)
Trace[345626216]: [624.999255ms] [624.999255ms] END
I1226 00:46:17.351790       1 trace.go:205] Trace[918027878]: "Get" url:/apis/user.openshift.io/v1/users/admin,user-agent:Go-http-client/2.0,audit-id:60209d41-26d8-4d62-b97e-61ead645da11,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 00:46:16.800) (total time: 551ms):
Trace[918027878]: ---"About to write a response" 551ms (00:46:17.351)
Trace[918027878]: [551.212363ms] [551.212363ms] END
I1226 00:46:17.353132       1 trace.go:205] Trace[1852912989]: "Create" url:/apis/oauth.openshift.io/v1/tokenreviews,user-agent:Go-http-client/2.0,audit-id:3dd3c02e-771f-4925-a6eb-413df11e8de7,client:100.64.0.4,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 00:46:16.171) (total time: 1182ms):
Trace[1852912989]: ---"Object stored in database" 1181ms (00:46:17.352)
Trace[1852912989]: [1.182051275s] [1.182051275s] END
E1226 00:46:17.410327       1 timeout.go:141] post-timeout activity - time-elapsed: 781.714435ms, GET "/readyz" result: <nil>
E1226 00:46:35.989322       1 timeout.go:141] post-timeout activity - time-elapsed: 363.683714ms, GET "/readyz" result: <nil>
E1226 00:46:36.888855       1 timeout.go:141] post-timeout activity - time-elapsed: 260.629637ms, GET "/readyz" result: <nil>
E1226 00:47:00.917711       1 timeout.go:141] post-timeout activity - time-elapsed: 292.251648ms, GET "/healthz" result: <nil>
E1226 00:47:01.208992       1 timeout.go:141] post-timeout activity - time-elapsed: 583.278307ms, GET "/readyz" result: <nil>
I1226 00:47:04.882755       1 trace.go:205] Trace[1835750204]: "Get" url:/apis/user.openshift.io/v1/users/admin,user-agent:Go-http-client/2.0,audit-id:a38dce6d-9fd0-4a58-af79-2315fc027078,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 00:47:03.396) (total time: 1486ms):
Trace[1835750204]: ---"About to write a response" 1486ms (00:47:04.882)
Trace[1835750204]: [1.486219802s] [1.486219802s] END
I1226 00:47:04.884444       1 trace.go:205] Trace[1487227888]: "Create" url:/apis/oauth.openshift.io/v1/tokenreviews,user-agent:Go-http-client/2.0,audit-id:54ac137a-c6b4-4865-95ac-973126369f10,client:100.64.0.3,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 00:47:02.936) (total time: 1947ms):
Trace[1487227888]: ---"Object stored in database" 1947ms (00:47:04.884)
Trace[1487227888]: [1.947640682s] [1.947640682s] END
E1226 00:47:21.177609       1 timeout.go:141] post-timeout activity - time-elapsed: 552.628079ms, GET "/healthz" result: <nil>
E1226 00:47:31.176416       1 timeout.go:141] post-timeout activity - time-elapsed: 548.510218ms, GET "/readyz" result: <nil>
I1226 00:47:32.104518       1 trace.go:205] Trace[821180809]: "Create" url:/apis/oauth.openshift.io/v1/oauthclients,user-agent:authentication-operator/v0.0.0 (linux/amd64) kubernetes/$Format,audit-id:b1f15ed9-f492-4f35-b060-a16054bbf951,client:10.128.0.24,accept:application/vnd.kubernetes.protobuf,application/json,protocol:HTTP/2.0 (26-Dec-2023 00:47:29.152) (total time: 2952ms):
Trace[821180809]: [2.952091001s] [2.952091001s] END
E1226 00:47:32.206463       1 timeout.go:141] post-timeout activity - time-elapsed: 577.730435ms, GET "/readyz" result: <nil>
E1226 00:49:21.473310       1 timeout.go:141] post-timeout activity - time-elapsed: 846.630834ms, GET "/healthz" result: <nil>
E1226 01:00:13.496795       1 timeout.go:141] post-timeout activity - time-elapsed: 2.870918106s, GET "/healthz" result: <nil>
E1226 01:00:20.780974       1 timeout.go:141] post-timeout activity - time-elapsed: 152.697191ms, GET "/readyz" result: <nil>
I1226 01:00:20.785533       1 trace.go:205] Trace[400958263]: "Get" url:/apis/oauth.openshift.io/v1/oauthclients/openshift-browser-client,user-agent:authentication-operator/v0.0.0 (linux/amd64) kubernetes/$Format,audit-id:e839c2b5-0107-404e-b67c-669154b57d4a,client:10.128.0.24,accept:application/vnd.kubernetes.protobuf,application/json,protocol:HTTP/2.0 (26-Dec-2023 01:00:17.860) (total time: 2925ms):
Trace[400958263]: ---"About to write a response" 2925ms (01:00:20.785)
Trace[400958263]: [2.925303945s] [2.925303945s] END
E1226 01:00:20.787296       1 timeout.go:141] post-timeout activity - time-elapsed: 161.496382ms, GET "/healthz" result: <nil>
E1226 03:00:07.992739       1 timeout.go:141] post-timeout activity - time-elapsed: 2.367238831s, GET "/readyz" result: <nil>
E1226 03:00:10.745454       1 timeout.go:141] post-timeout activity - time-elapsed: 119.239868ms, GET "/readyz" result: <nil>
E1226 03:00:10.755679       1 timeout.go:141] post-timeout activity - time-elapsed: 123.623948ms, GET "/healthz" result: <nil>
E1226 04:56:35.917597       1 timeout.go:141] post-timeout activity - time-elapsed: 289.787852ms, GET "/readyz" result: <nil>
E1226 04:58:00.616610       1 timeout.go:141] post-timeout activity - time-elapsed: 4.982498748s, GET "/readyz" result: <nil>
E1226 04:58:01.464466       1 timeout.go:141] post-timeout activity - time-elapsed: 835.049972ms, GET "/healthz" result: <nil>
E1226 05:00:12.480100       1 timeout.go:141] post-timeout activity - time-elapsed: 811.53565ms, GET "/readyz" result: <nil>
E1226 05:00:12.707210       1 timeout.go:141] post-timeout activity - time-elapsed: 2.081115964s, GET "/readyz" result: <nil>
E1226 05:00:13.459692       1 timeout.go:141] post-timeout activity - time-elapsed: 2.833521176s, GET "/healthz" result: <nil>
E1226 05:00:41.743086       1 timeout.go:141] post-timeout activity - time-elapsed: 1.11586928s, GET "/readyz" result: <nil>
E1226 05:00:53.016423       1 timeout.go:141] post-timeout activity - time-elapsed: 2.389978537s, GET "/readyz" result: <nil>
E1226 05:00:54.949364       1 timeout.go:141] post-timeout activity - time-elapsed: 4.322119444s, GET "/healthz" result: <nil>
E1226 05:00:56.347506       1 timeout.go:141] post-timeout activity - time-elapsed: 721.686255ms, GET "/readyz" result: <nil>
E1226 05:00:58.456077       1 timeout.go:141] post-timeout activity - time-elapsed: 6.828235014s, GET "/readyz" result: <nil>
E1226 07:00:11.708511       1 timeout.go:141] post-timeout activity - time-elapsed: 1.082333419s, GET "/healthz" result: <nil>
E1226 07:00:13.900131       1 timeout.go:141] post-timeout activity - time-elapsed: 3.273334835s, GET "/readyz" result: <nil>
I1226 07:00:18.058383       1 trace.go:205] Trace[1619763876]: "Create" url:/apis/oauth.openshift.io/v1/oauthclients,user-agent:authentication-operator/v0.0.0 (linux/amd64) kubernetes/$Format,audit-id:70631fc7-0a1e-4bca-9831-4865eb9bacfd,client:10.128.0.24,accept:application/vnd.kubernetes.protobuf,application/json,protocol:HTTP/2.0 (26-Dec-2023 07:00:15.683) (total time: 2375ms):
Trace[1619763876]: [2.375269715s] [2.375269715s] END
E1226 09:00:12.192091       1 timeout.go:141] post-timeout activity - time-elapsed: 1.566646161s, GET "/readyz" result: <nil>
E1226 09:00:12.640624       1 timeout.go:141] post-timeout activity - time-elapsed: 1.013176226s, GET "/readyz" result: <nil>
E1226 09:00:13.220685       1 timeout.go:141] post-timeout activity - time-elapsed: 2.595322835s, GET "/healthz" result: <nil>
E1226 11:00:11.960050       1 timeout.go:141] post-timeout activity - time-elapsed: 1.335156291s, GET "/readyz" result: <nil>
E1226 11:00:13.447648       1 timeout.go:141] post-timeout activity - time-elapsed: 2.82240345s, GET "/healthz" result: <nil>
E1226 11:00:13.576943       1 timeout.go:141] post-timeout activity - time-elapsed: 1.949141304s, GET "/readyz" result: <nil>
E1226 11:00:21.347853       1 timeout.go:141] post-timeout activity - time-elapsed: 721.708037ms, GET "/readyz" result: <nil>
E1226 11:00:21.445506       1 timeout.go:141] post-timeout activity - time-elapsed: 819.267863ms, GET "/healthz" result: <nil>
E1226 11:00:48.700008       1 timeout.go:141] post-timeout activity - time-elapsed: 3.06288159s, GET "/readyz" result: <nil>
E1226 11:00:52.301680       1 timeout.go:141] post-timeout activity - time-elapsed: 1.675895299s, GET "/readyz" result: <nil>
E1226 11:00:54.393695       1 timeout.go:141] post-timeout activity - time-elapsed: 7.764705569s, GET "/readyz" result: <nil>
E1226 11:00:57.227631       1 timeout.go:141] post-timeout activity - time-elapsed: 6.601828431s, GET "/healthz" result: <nil>
E1226 11:01:00.581152       1 timeout.go:141] post-timeout activity - time-elapsed: 4.954644987s, GET "/readyz" result: <nil>
E1226 11:01:06.615124       1 timeout.go:141] post-timeout activity - time-elapsed: 989.835469ms, GET "/readyz" result: <nil>
E1226 11:01:06.973981       1 timeout.go:141] post-timeout activity - time-elapsed: 347.22129ms, GET "/readyz" result: <nil>
E1226 11:01:10.907682       1 timeout.go:141] post-timeout activity - time-elapsed: 281.653182ms, GET "/healthz" result: <nil>
E1226 13:00:12.023711       1 timeout.go:141] post-timeout activity - time-elapsed: 396.458697ms, GET "/readyz" result: <nil>
E1226 13:00:12.589990       1 timeout.go:141] post-timeout activity - time-elapsed: 1.962969722s, GET "/readyz" result: <nil>
E1226 13:00:12.590368       1 timeout.go:141] post-timeout activity - time-elapsed: 1.962269461s, GET "/healthz" result: <nil>
I1226 13:00:19.017448       1 trace.go:205] Trace[1309654552]: "Get" url:/apis/oauth.openshift.io/v1/oauthaccesstokens/sha256~55ZUca-YW2Z3cWeYbfGd0f0rfwywhGSj-TKLhYt34WY,user-agent:Go-http-client/2.0,audit-id:c856bc37-5fcc-43a9-9012-82d2c6ec14c3,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 13:00:16.531) (total time: 2485ms):
Trace[1309654552]: ---"About to write a response" 2484ms (13:00:19.016)
Trace[1309654552]: [2.485159685s] [2.485159685s] END
I1226 13:00:19.054787       1 trace.go:205] Trace[1501531194]: "Create" url:/apis/oauth.openshift.io/v1/tokenreviews,user-agent:Go-http-client/2.0,audit-id:ad43b5ec-dfa6-4916-b34d-c918fbe42225,client:100.64.0.3,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 13:00:16.527) (total time: 2527ms):
Trace[1501531194]: ---"Object stored in database" 2526ms (13:00:19.054)
Trace[1501531194]: [2.527125454s] [2.527125454s] END
I1226 13:00:20.861930       1 trace.go:205] Trace[167477318]: "Get" url:/apis/oauth.openshift.io/v1/oauthaccesstokens/sha256~ExZyU6Ziu9B3dZGjrHaWMy1hxonSHIsHyY3Cipmq0XA,user-agent:Go-http-client/2.0,audit-id:0867fb3d-ad0e-4d3c-8462-3f75fc24779d,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 13:00:19.783) (total time: 1078ms):
Trace[167477318]: ---"About to write a response" 1077ms (13:00:20.861)
Trace[167477318]: [1.078123664s] [1.078123664s] END
I1226 13:00:20.897612       1 trace.go:205] Trace[1892937976]: "Create" url:/apis/oauth.openshift.io/v1/tokenreviews,user-agent:Go-http-client/2.0,audit-id:3b2d6d0f-4a76-4954-bbe6-2b8e4fe9cf82,client:100.64.0.3,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 13:00:19.781) (total time: 1115ms):
Trace[1892937976]: ---"Object stored in database" 1115ms (13:00:20.897)
Trace[1892937976]: [1.115958392s] [1.115958392s] END
E1226 13:29:29.465169       1 timeout.go:141] post-timeout activity - time-elapsed: 2.835504287s, GET "/readyz" result: <nil>
E1226 13:29:29.488236       1 timeout.go:141] post-timeout activity - time-elapsed: 3.863201812s, GET "/readyz" result: <nil>
I1226 13:37:11.617489       1 trace.go:205] Trace[808850183]: "Get" url:/apis/user.openshift.io/v1/users/admin,user-agent:Go-http-client/2.0,audit-id:72bcbc73-1eeb-434d-9bea-b3de54975eff,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 13:37:10.933) (total time: 684ms):
Trace[808850183]: ---"About to write a response" 684ms (13:37:11.617)
Trace[808850183]: [684.334237ms] [684.334237ms] END
I1226 13:37:11.619508       1 trace.go:205] Trace[1277672001]: "Create" url:/apis/oauth.openshift.io/v1/tokenreviews,user-agent:Go-http-client/2.0,audit-id:e6029958-b3e2-4bd2-a2b6-bea9fecc3018,client:100.64.0.3,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 13:37:10.660) (total time: 958ms):
Trace[1277672001]: ---"Object stored in database" 958ms (13:37:11.619)
Trace[1277672001]: [958.948357ms] [958.948357ms] END
E1226 13:37:15.932839       1 timeout.go:141] post-timeout activity - time-elapsed: 307.201864ms, GET "/readyz" result: <nil>
E1226 13:37:21.027965       1 timeout.go:141] post-timeout activity - time-elapsed: 402.372212ms, GET "/readyz" result: <nil>
E1226 14:39:21.807505       1 timeout.go:141] post-timeout activity - time-elapsed: 1.181595454s, GET "/readyz" result: <nil>
E1226 14:39:21.972567       1 timeout.go:141] post-timeout activity - time-elapsed: 1.347241839s, GET "/healthz" result: <nil>
E1226 14:39:23.132220       1 timeout.go:141] post-timeout activity - time-elapsed: 1.502722876s, GET "/readyz" result: <nil>
E1226 15:00:11.258817       1 timeout.go:141] post-timeout activity - time-elapsed: 633.213947ms, GET "/healthz" result: <nil>
E1226 15:00:11.731766       1 timeout.go:141] post-timeout activity - time-elapsed: 1.105309966s, GET "/readyz" result: <nil>
E1226 15:00:12.157859       1 timeout.go:141] post-timeout activity - time-elapsed: 529.617707ms, GET "/readyz" result: <nil>
E1226 17:00:11.350018       1 watcher.go:227] watch chan error: etcdserver: no leader
W1226 17:00:11.350527       1 reflector.go:442] storage/cacher.go:/oauth/accesstokens: watch of *oauth.OAuthAccessToken ended with: Internal error occurred: etcdserver: no leader
E1226 17:00:11.876161       1 timeout.go:141] post-timeout activity - time-elapsed: 245.772808ms, GET "/readyz" result: <nil>
E1226 17:00:11.907553       1 timeout.go:141] post-timeout activity - time-elapsed: 1.281809056s, GET "/healthz" result: <nil>
W1226 17:00:12.351097       1 cacher.go:150] Terminating all watchers from cacher *oauth.OAuthAccessToken
E1226 17:00:12.896140       1 timeout.go:141] post-timeout activity - time-elapsed: 2.27038633s, GET "/readyz" result: <nil>
I1226 17:00:15.799416       1 trace.go:205] Trace[1331980229]: "List(recursive=true) etcd3" key:/oauth/accesstokens,resourceVersion:,resourceVersionMatch:,limit:10000,continue: (26-Dec-2023 17:00:12.351) (total time: 3448ms):
Trace[1331980229]: [3.448079825s] [3.448079825s] END
I1226 17:00:15.805081       1 cacher.go:410] cacher (*oauth.OAuthAccessToken): initialized
E1226 17:00:15.860415       1 timeout.go:141] post-timeout activity - time-elapsed: 234.326857ms, GET "/readyz" result: <nil>
E1226 17:00:41.347656       1 timeout.go:141] post-timeout activity - time-elapsed: 720.757556ms, GET "/readyz" result: <nil>
E1226 17:00:41.654369       1 timeout.go:141] post-timeout activity - time-elapsed: 25.163548ms, GET "/readyz" result: <nil>
E1226 17:00:47.854730       1 timeout.go:141] post-timeout activity - time-elapsed: 2.226872537s, GET "/readyz" result: <nil>
E1226 17:00:53.015426       1 timeout.go:141] post-timeout activity - time-elapsed: 2.388775752s, GET "/readyz" result: <nil>
I1226 17:00:54.793562       1 trace.go:205] Trace[971801311]: "Get" url:/apis/oauth.openshift.io/v1/oauthaccesstokens/sha256~55ZUca-YW2Z3cWeYbfGd0f0rfwywhGSj-TKLhYt34WY,user-agent:Go-http-client/2.0,audit-id:4473c9ca-21d7-45e4-a754-1b0b882b665d,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 17:00:50.706) (total time: 4086ms):
Trace[971801311]: ---"About to write a response" 4086ms (17:00:54.793)
Trace[971801311]: [4.086609429s] [4.086609429s] END
E1226 17:00:54.799122       1 timeout.go:141] post-timeout activity - time-elapsed: 4.172739574s, GET "/healthz" result: <nil>
E1226 17:00:56.049689       1 timeout.go:141] post-timeout activity - time-elapsed: 423.182573ms, GET "/readyz" result: <nil>
I1226 17:00:56.822045       1 trace.go:205] Trace[1432708023]: "Get" url:/apis/user.openshift.io/v1/users/admin,user-agent:Go-http-client/2.0,audit-id:6a3cd297-80ab-4b73-bcb2-5a9c2b12206e,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 17:00:54.796) (total time: 2025ms):
Trace[1432708023]: ---"About to write a response" 2025ms (17:00:56.821)
Trace[1432708023]: [2.025510716s] [2.025510716s] END
I1226 17:00:56.823796       1 trace.go:205] Trace[846840899]: "Create" url:/apis/oauth.openshift.io/v1/tokenreviews,user-agent:Go-http-client/2.0,audit-id:2764212f-51fb-495a-8e49-1d2c9427b7f5,client:100.64.0.2,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 17:00:50.704) (total time: 6119ms):
Trace[846840899]: ---"Object stored in database" 6118ms (17:00:56.823)
Trace[846840899]: [6.119016755s] [6.119016755s] END
E1226 17:01:01.079144       1 timeout.go:141] post-timeout activity - time-elapsed: 453.292179ms, GET "/readyz" result: <nil>
E1226 17:01:01.120627       1 timeout.go:141] post-timeout activity - time-elapsed: 494.810823ms, GET "/healthz" result: <nil>
E1226 17:01:13.652302       1 timeout.go:141] post-timeout activity - time-elapsed: 3.026552293s, GET "/readyz" result: <nil>
E1226 17:01:16.422633       1 timeout.go:141] post-timeout activity - time-elapsed: 785.201171ms, GET "/readyz" result: <nil>
E1226 17:01:23.353060       1 timeout.go:141] post-timeout activity - time-elapsed: 6.722278005s, GET "/readyz" result: <nil>
{"level":"warn","ts":"2023-12-26T17:01:25.501Z","logger":"etcd-client","caller":"[email protected]/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc000002000/192.168.102.71:2379","attempt":0,"error":"rpc error: code = Unavailable desc = etcdserver: leader changed"}
E1226 17:01:27.821292       1 timeout.go:141] post-timeout activity - time-elapsed: 7.195883521s, GET "/readyz" result: <nil>
E1226 17:01:28.599445       1 timeout.go:141] post-timeout activity - time-elapsed: 2.972668501s, GET "/readyz" result: <nil>
E1226 17:01:32.657717       1 timeout.go:141] post-timeout activity - time-elapsed: 2.031503952s, GET "/healthz" result: <nil>
E1226 17:01:35.096136       1 timeout.go:141] post-timeout activity - time-elapsed: 4.469931586s, GET "/readyz" result: <nil>
E1226 17:01:38.483278       1 timeout.go:141] post-timeout activity - time-elapsed: 2.856903139s, GET "/readyz" result: <nil>
E1226 17:01:47.733073       1 timeout.go:141] post-timeout activity - time-elapsed: 1.103604655s, GET "/readyz" result: <nil>
E1226 17:01:50.821030       1 timeout.go:141] post-timeout activity - time-elapsed: 5.194425928s, GET "/readyz" result: <nil>
{"level":"warn","ts":"2023-12-26T17:01:55.386Z","logger":"etcd-client","caller":"[email protected]/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc000002000/192.168.102.71:2379","attempt":0,"error":"rpc error: code = Unavailable desc = etcdserver: leader changed"}
{"level":"warn","ts":"2023-12-26T17:01:55.394Z","logger":"etcd-client","caller":"[email protected]/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc000002000/192.168.102.71:2379","attempt":0,"error":"rpc error: code = Unavailable desc = etcdserver: leader changed"}
E1226 17:01:55.452499       1 timeout.go:141] post-timeout activity - time-elapsed: 4.827600305s, GET "/readyz" result: <nil>
E1226 17:01:55.455643       1 timeout.go:141] post-timeout activity - time-elapsed: 4.830803628s, GET "/healthz" result: <nil>
E1226 17:01:56.996612       1 timeout.go:141] post-timeout activity - time-elapsed: 1.344642405s, GET "/readyz" result: <nil>
E1226 17:02:00.740541       1 timeout.go:141] post-timeout activity - time-elapsed: 115.084863ms, GET "/readyz" result: <nil>
I1226 17:02:00.741318       1 trace.go:205] Trace[22067487]: "Get" url:/apis/oauth.openshift.io/v1/oauthclients/console,user-agent:console/v0.0.0 (linux/amd64) kubernetes/$Format,audit-id:e668632b-d8e3-49b8-9dcc-e3055ebd0ba4,client:192.168.102.73,accept:application/vnd.kubernetes.protobuf,application/json,protocol:HTTP/2.0 (26-Dec-2023 17:01:58.606) (total time: 2135ms):
Trace[22067487]: ---"About to write a response" 2135ms (17:02:00.741)
Trace[22067487]: [2.135242939s] [2.135242939s] END
I1226 17:02:04.989135       1 trace.go:205] Trace[871336461]: "Get" url:/apis/oauth.openshift.io/v1/oauthaccesstokens/sha256~I8aJoIpkUIJbRdzpiRslJRTKSoFF2kGJU1H2xemh3M0,user-agent:Go-http-client/2.0,audit-id:2d1cb6b9-aae9-46f0-946e-6b4722ac77ba,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 17:02:04.405) (total time: 583ms):
Trace[871336461]: ---"About to write a response" 582ms (17:02:04.988)
Trace[871336461]: [583.104959ms] [583.104959ms] END
I1226 17:02:04.996176       1 trace.go:205] Trace[1656012856]: "Create" url:/apis/oauth.openshift.io/v1/tokenreviews,user-agent:Go-http-client/2.0,audit-id:2c2e2a2c-54cd-499d-a191-51792c383315,client:100.64.0.2,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 17:02:04.404) (total time: 592ms):
Trace[1656012856]: ---"Object stored in database" 591ms (17:02:04.995)
Trace[1656012856]: [592.030595ms] [592.030595ms] END
I1226 18:00:33.595625       1 trace.go:205] Trace[818350549]: "Get" url:/apis/oauth.openshift.io/v1/oauthaccesstokens/sha256~55ZUca-YW2Z3cWeYbfGd0f0rfwywhGSj-TKLhYt34WY,user-agent:Go-http-client/2.0,audit-id:35e3a9c0-c327-4e8b-9101-87f53fbe4767,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 18:00:32.894) (total time: 700ms):
Trace[818350549]: ---"About to write a response" 700ms (18:00:33.595)
Trace[818350549]: [700.566728ms] [700.566728ms] END
I1226 18:00:34.492246       1 trace.go:205] Trace[1136436500]: "Get" url:/apis/user.openshift.io/v1/users/admin,user-agent:Go-http-client/2.0,audit-id:9dab60e6-8dd1-4da6-956c-26529cd07dff,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 18:00:33.598) (total time: 893ms):
Trace[1136436500]: ---"About to write a response" 893ms (18:00:34.492)
Trace[1136436500]: [893.379966ms] [893.379966ms] END
I1226 18:00:34.494680       1 trace.go:205] Trace[1981663801]: "Create" url:/apis/oauth.openshift.io/v1/tokenreviews,user-agent:Go-http-client/2.0,audit-id:9d7db6d0-ac28-4685-97f4-cbd5f2711a26,client:100.64.0.4,accept:application/json, */*,protocol:HTTP/2.0 (26-Dec-2023 18:00:32.890) (total time: 1604ms):
Trace[1981663801]: ---"Object stored in database" 1603ms (18:00:34.494)
Trace[1981663801]: [1.604455142s] [1.604455142s] END
E1226 19:00:12.606323       1 timeout.go:141] post-timeout activity - time-elapsed: 1.979050619s, GET "/healthz" result: <nil>
E1226 19:00:12.894164       1 timeout.go:141] post-timeout activity - time-elapsed: 1.26596239s, GET "/readyz" result: <nil>
E1226 19:00:13.639604       1 timeout.go:141] post-timeout activity - time-elapsed: 3.01217414s, GET "/readyz" result: <nil>
I1226 19:00:15.041486       1 trace.go:205] Trace[1976791634]: "Create" url:/apis/oauth.openshift.io/v1/oauthclients,user-agent:authentication-operator/v0.0.0 (linux/amd64) kubernetes/$Format,audit-id:5204b13d-68be-494e-a1ff-6f0952854405,client:10.128.0.24,accept:application/vnd.kubernetes.protobuf,application/json,protocol:HTTP/2.0 (26-Dec-2023 19:00:14.530) (total time: 511ms):
Trace[1976791634]: [511.071934ms] [511.071934ms] END
I1226 19:00:15.749197       1 trace.go:205] Trace[328504639]: "Get" url:/apis/oauth.openshift.io/v1/oauthclients/openshift-challenging-client,user-agent:authentication-operator/v0.0.0 (linux/amd64) kubernetes/$Format,audit-id:c9f2e829-b662-4a1c-bfa2-703785564cff,client:10.128.0.24,accept:application/vnd.kubernetes.protobuf,application/json,protocol:HTTP/2.0 (26-Dec-2023 19:00:15.076) (total time: 672ms):
Trace[328504639]: ---"About to write a response" 672ms (19:00:15.749)
Trace[328504639]: [672.922183ms] [672.922183ms] END
E1226 19:00:15.765682       1 timeout.go:141] post-timeout activity - time-elapsed: 139.350364ms, GET "/readyz" result: <nil>
E1226 21:00:15.787587       1 timeout.go:141] post-timeout activity - time-elapsed: 28.163222ms, GET "/readyz" result: <nil>
E1226 21:21:36.539007       1 timeout.go:141] post-timeout activity - time-elapsed: 912.579352ms, GET "/readyz" result: <nil>
E1226 21:35:27.751672       1 timeout.go:141] post-timeout activity - time-elapsed: 2.12206876s, GET "/readyz" result: <nil>
E1226 21:50:27.229692       1 timeout.go:141] post-timeout activity - time-elapsed: 1.60001084s, GET "/readyz" result: <nil>
E1226 21:50:27.675533       1 timeout.go:141] post-timeout activity - time-elapsed: 1.04442963s, GET "/readyz" result: <nil>
E1226 23:00:12.841422       1 timeout.go:141] post-timeout activity - time-elapsed: 2.215100615s, GET "/healthz" result: <nil>
I1226 23:00:18.351461       1 trace.go:205] Trace[1632258765]: "Get" url:/apis/oauth.openshift.io/v1/oauthclients/console,user-agent:console/v0.0.0 (linux/amd64) kubernetes/$Format,audit-id:d90cfc28-7273-4338-8788-1fb9a768a16b,client:192.168.102.73,accept:application/vnd.kubernetes.protobuf,application/json,protocol:HTTP/2.0 (26-Dec-2023 23:00:16.614) (total time: 1736ms):
Trace[1632258765]: ---"About to write a response" 1736ms (23:00:18.351)
Trace[1632258765]: [1.736904383s] [1.736904383s] END
E1226 23:00:47.620261       1 timeout.go:141] post-timeout activity - time-elapsed: 993.423064ms, GET "/readyz" result: <nil>
E1226 23:00:48.935450       1 timeout.go:141] post-timeout activity - time-elapsed: 3.309823789s, GET "/readyz" result: <nil>
E1226 23:00:50.934805       1 timeout.go:141] post-timeout activity - time-elapsed: 308.682268ms, GET "/readyz" result: <nil>
E1226 23:00:53.292239       1 timeout.go:141] post-timeout activity - time-elapsed: 2.666071036s, GET "/healthz" result: <nil>
E1226 23:00:56.045535       1 timeout.go:141] post-timeout activity - time-elapsed: 416.353627ms, GET "/readyz" result: <nil>
E1227 00:00:18.169757       1 timeout.go:141] post-timeout activity - time-elapsed: 2.536633921s, GET "/readyz" result: <nil>
E1227 00:00:22.601317       1 watcher.go:227] watch chan error: etcdserver: no leader
W1227 00:00:22.601656       1 reflector.go:442] storage/cacher.go:/groups: watch of *user.Group ended with: Internal error occurred: etcdserver: no leader
E1227 00:00:22.644475       1 watcher.go:227] watch chan error: etcdserver: no leader
E1227 00:00:22.644746       1 watcher.go:227] watch chan error: etcdserver: no leader
W1227 00:00:22.645295       1 reflector.go:442] storage/cacher.go:/oauth/clients: watch of *oauth.OAuthClient ended with: Internal error occurred: etcdserver: no leader
W1227 00:00:22.645396       1 reflector.go:442] storage/cacher.go:/useridentities: watch of *user.Identity ended with: Internal error occurred: etcdserver: no leader
{"level":"warn","ts":"2023-12-27T00:00:22.843Z","logger":"etcd-client","caller":"[email protected]/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc000002000/192.168.102.71:2379","attempt":0,"error":"rpc error: code = Unavailable desc = etcdserver: leader changed"}
{"level":"warn","ts":"2023-12-27T00:00:22.855Z","logger":"etcd-client","caller":"[email protected]/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc000002000/192.168.102.71:2379","attempt":0,"error":"rpc error: code = Unavailable desc = etcdserver: leader changed"}
E1227 00:00:23.525912       1 timeout.go:141] post-timeout activity - time-elapsed: 2.899729118s, GET "/readyz" result: <nil>
E1227 00:00:23.581371       1 timeout.go:141] post-timeout activity - time-elapsed: 2.955180526s, GET "/healthz" result: <nil>
W1227 00:00:23.603042       1 cacher.go:150] Terminating all watchers from cacher *user.Group
E1227 00:00:23.616032       1 timeout.go:141] post-timeout activity - time-elapsed: 1.987429382s, GET "/readyz" result: <nil>
I1227 00:00:23.632726       1 cacher.go:410] cacher (*user.Group): initialized
W1227 00:00:23.646988       1 cacher.go:150] Terminating all watchers from cacher *oauth.OAuthClient
I1227 00:00:23.665727       1 cacher.go:410] cacher (*oauth.OAuthClient): initialized
I1227 00:00:23.668858       1 cacher.go:410] cacher (*user.Identity): initialized
I1227 00:00:30.502758       1 trace.go:205] Trace[1145503152]: "Get" url:/apis/oauth.openshift.io/v1/oauthaccesstokens/sha256~I8aJoIpkUIJbRdzpiRslJRTKSoFF2kGJU1H2xemh3M0,user-agent:Go-http-client/2.0,audit-id:b5646c4a-d11b-4dc6-8c25-569936aea1a9,client:::1,accept:application/json, */*,protocol:HTTP/2.0 (27-Dec-2023 00:00:29.893) (total time: 609ms):
Trace[1145503152]: ---"About to write a response" 609ms (00:00:30.502)
Trace[1145503152]: [609.536234ms] [609.536234ms] END
I1227 00:00:30.516693       1 trace.go:205] Trace[864240657]: "Create" url:/apis/oauth.openshift.io/v1/tokenreviews,user-agent:Go-http-client/2.0,audit-id:94aef436-1a14-48b1-8edf-c988485b211c,client:100.64.0.3,accept:application/json, */*,protocol:HTTP/2.0 (27-Dec-2023 00:00:29.891) (total time: 625ms):
Trace[864240657]: ---"Object stored in database" 625ms (00:00:30.516)
Trace[864240657]: [625.388646ms] [625.388646ms] END
http2: server connection error from 100.64.0.4:40732: connection error: PROTOCOL_ERROR
E1227 01:00:05.704740       1 timeout.go:141] post-timeout activity - time-elapsed: 73.55792ms, GET "/readyz" result: <nil>
E1227 01:00:07.159708       1 timeout.go:141] post-timeout activity - time-elapsed: 530.455154ms, GET "/readyz" result: <nil>
E1227 01:00:11.436172       1 timeout.go:141] post-timeout activity - time-elapsed: 810.581154ms, GET "/readyz" result: <nil>
I1227 01:00:11.437859       1 trace.go:205] Trace[1817491033]: "Create" url:/apis/oauth.openshift.io/v1/oauthclients,user-agent:authentication-operator/v0.0.0 (linux/amd64) kubernetes/$Format,audit-id:acc44200-4fd1-474b-a5d9-0506d837e912,client:10.128.0.24,accept:application/vnd.kubernetes.protobuf,application/json,protocol:HTTP/2.0 (27-Dec-2023 01:00:09.080) (total time: 2357ms):
Trace[1817491033]: [2.357174682s] [2.357174682s] END
E1227 01:00:12.276326       1 timeout.go:141] post-timeout activity - time-elapsed: 1.650648633s, GET "/healthz" result: <nil>
http2: server: error reading preface from client 10.128.0.2:47276: read tcp 10.130.0.5:8443->10.128.0.2:47276: read: connection reset by peer
E1227 02:39:21.400483       1 timeout.go:141] post-timeout activity - time-elapsed: 774.743372ms, GET "/healthz" result: <nil>
E1227 02:39:31.593484       1 timeout.go:141] post-timeout activity - time-elapsed: 959.616561ms, GET "/readyz" result: <nil>

Version

4.12.0-0.okd-2023-04-16-041331

How reproducible

Log bundle

[vrutkovs]

Please attach (or upload to the public file sharing service) must-gather archive

[maps1995]

You can download the file from the below link:

https://easyupload.io/layax0

[vrutkovs]

authentication not Degraded there, seems to be running fine.

I see a lot of "apply request took too long" in etcd, which means storage is not fast enough for it. It would manifest itself as random slowdowns and "Trace" log entries, showing slow responses