Bug 1886442

$ oc get clusterversion
NAME      VERSION                             AVAILABLE   PROGRESSING   SINCE   STATUS
version   4.6.0-0.nightly-2020-10-10-041109   True        False         26m     Cluster version is 4.6.0-0.nightly-2020-10-10-041109

$ oc get FlowSchema openshift-oauth-server
NAME                     PRIORITYLEVEL   MATCHINGPRECEDENCE   DISTINGUISHERMETHOD   AGE   MISSINGPL
openshift-oauth-server   workload-high   1000                 ByUser                43m   False

But didn't find the following similar message in any logs,

> I1007 13:36:37.960017      18 queueset.go:601] QS(workload-high) at r=2020-10-07 13:36:37.960004077 v=93.148279199s: dispatching request &request.RequestInfo{IsResourceRequest:true, Path:"/apis/authorization.k8s.io/v1/subjectaccessreviews", Verb:"create", APIPrefix:"apis", APIGroup:"authorization.k8s.io", APIVersion:"v1", Namespace:"", Resource:"subjectaccessreviews", Subresource:"", Name:"", Parts:[]string{"subjectaccessreviews"}} &user.DefaultInfo{Name:"system:serviceaccount:openshift-authentication:oauth-openshift", UID:"21638bc1-af75-4749-acc0-a8e952157bf2", Groups:[]string{"system:serviceaccounts", "system:serviceaccounts:openshift-authentication", "system:authenticated"}, Extra:map[string][]string(nil)} from queue 97 with virtual start time 93.148279199s, queue will have 0 waiting & 1 executing

Searching above message with the following command lines:

$ oauth_pods=$(oc get pods -A | grep 'openshift-oauth-apiserver' | awk '{print $2}')

$ for pod in $oauth_pods; do oc -n openshift-oauth-apiserver logs $pod | grep 'dispatching request';done

Hi kewang,
you need to search the kube-apiserver logs. This is to identify what priority kube-apiserver assigns requsts from oauth server (oauth -> kube-apiserver). So we need to check the kube-apiserver logs.

Hi akashem, still got nothing with checking apiserver logs, what else need I to do?

$ kas_pods=$(oc get pods -n openshift-kube-apiserver | grep 'kube-apiserver' | awk '{print $1}')

$ for pod in $kas_pods; do oc -n openshift-kube-apiserver logs $pod | grep 'dispatching request';done

After changed kubeapiserver/cluster loglevel to Trace, will catch the following message which we want.

I1012 15:18:54.447303      17 queueset.go:601] QS(workload-low) at r=2020-10-12 15:18:54.447291206 v=8.628825495s: dispatching request &request.RequestInfo{IsResourceRequest:true, Path:"/apis/rbac.authorization.k8s.io/v1/namespaces/openshift-kube-scheduler/rolebindings/system:openshift:sa-listing-configmaps", Verb:"get", APIPrefix:"apis", APIGroup:"rbac.authorization.k8s.io", APIVersion:"v1", Namespace:"openshift-kube-scheduler", Resource:"rolebindings", Subresource:"", Name:"system:openshift:sa-listing-configmaps", Parts:[]string{"rolebindings", "system:openshift:sa-listing-configmaps"}} &user.DefaultInfo{Name:"system:serviceaccount:openshift-kube-scheduler-operator:openshift-kube-scheduler-operator", UID:"d5f2ce4c-98ef-4936-b12b-45b08de98eeb", Groups:[]string{"system:serviceaccounts", "system:serviceaccounts:openshift-kube-scheduler-operator", "system:authenticated"}, Extra:map[string][]string(nil)} from queue 71 with virtual start time 8.628825495s, queue will have 0 waiting & 1 executing

Hi kewang,

The log like must satisfy the following:
- grep for "dispatching request" to find the log line that p&f outputs when it assigns an incoming request to priority.
- the group of the user must originate from "system:serviceaccount:openshift-authentication:oauth-openshift" (oauth server)
- and the matching queue set is expected to be "workload-high"

> oc -n openshift-kube-apiserver logs {kube-apiserver-pod}  -c kube-apiserver | grep 'dispatching request' | grep 'system:serviceaccount:openshift-authentication:oauth-openshift'


The above log line you posted does not match. Can you please redo the test?
Thanks!

Sorry, I didn't check it carefully. The posted log is not detailed enough, I rechecked, below are matched.

$ oc -n openshift-kube-apiserver logs kube-apiserver-control-plane-0  -c kube-apiserver | grep 'dispatching request' | grep 'system:serviceaccount:openshift-authentication:oauth-openshift'

I1014 04:11:07.236645      18 queueset.go:601] QS(workload-high) at r=2020-10-14 04:11:07.233100336 v=77.731590623s: dispatching request &request.RequestInfo{IsResourceRequest:true, Path:"/apis/authentication.k8s.io/v1/tokenreviews", Verb:"create", APIPrefix:"apis", APIGroup:"authentication.k8s.io", APIVersion:"v1", Namespace:"", Resource:"tokenreviews", Subresource:"", Name:"", Parts:[]string{"tokenreviews"}} &user.DefaultInfo{Name:"system:serviceaccount:openshift-authentication:oauth-openshift", UID:"cca2648a-d0ba-4218-8df2-6387ab8f77cd", Groups:[]string{"system:serviceaccounts", "system:serviceaccounts:openshift-authentication", "system:authenticated"}, Extra:map[string][]string(nil)} from queue 97 with virtual start time 77.731590623s, queue will have 0 waiting & 1 executing

I1014 04:11:07.255768      18 queueset.go:601] QS(workload-high) at r=2020-10-14 04:11:07.255736687 v=77.743655943s: dispatching request &request.RequestInfo{IsResourceRequest:true, Path:"/apis/authorization.k8s.io/v1/subjectaccessreviews", Verb:"create", APIPrefix:"apis", APIGroup:"authorization.k8s.io", APIVersion:"v1", Namespace:"", Resource:"subjectaccessreviews", Subresource:"", Name:"", Parts:[]string{"subjectaccessreviews"}} &user.DefaultInfo{Name:"system:serviceaccount:openshift-authentication:oauth-openshift", UID:"cca2648a-d0ba-4218-8df2-6387ab8f77cd", Groups:[]string{"system:serviceaccounts", "system:serviceaccounts:openshift-authentication", "system:authenticated"}, Extra:map[string][]string(nil)} from queue 97 with virtual start time 77.743655943s, queue will have 0 waiting & 1 executing

I1014 04:11:37.229729      18 queueset.go:601] QS(workload-high) at r=2020-10-14 04:11:37.228363137 v=78.743402326s: dispatching request &request.RequestInfo{IsResourceRequest:true, Path:"/apis/authentication.k8s.io/v1/tokenreviews", Verb:"create", APIPrefix:"apis", APIGroup:"authentication.k8s.io", APIVersion:"v1", Namespace:"", Resource:"tokenreviews", Subresource:"", Name:"", Parts:[]string{"tokenreviews"}} &user.DefaultInfo{Name:"system:serviceaccount:openshift-authentication:oauth-openshift", UID:"cca2648a-d0ba-4218-8df2-6387ab8f77cd", Groups:[]string{"system:serviceaccounts", "system:serviceaccounts:openshift-authentication", "system:authenticated"}, Extra:map[string][]string(nil)} from queue 97 with virtual start time 78.743402326s, queue will have 0 waiting & 1 executing

I1014 04:11:37.241713      18 queueset.go:601] QS(workload-high) at r=2020-10-14 04:11:37.241675867 v=78.750424306s: dispatching request &request.RequestInfo{IsResourceRequest:true, Path:"/apis/authorization.k8s.io/v1/subjectaccessreviews", Verb:"create", APIPrefix:"apis", APIGroup:"authorization.k8s.io", APIVersion:"v1", Namespace:"", Resource:"subjectaccessreviews", Subresource:"", Name:"", Parts:[]string{"subjectaccessreviews"}} &user.DefaultInfo{Name:"system:serviceaccount:openshift-authentication:oauth-openshift", UID:"cca2648a-d0ba-4218-8df2-6387ab8f77cd", Groups:[]string{"system:serviceaccounts", "system:serviceaccounts:openshift-authentication", "system:authenticated"}, Extra:map[string][]string(nil)} from queue 97 with virtual start time 78.750424306s, queue will have 0 waiting & 1 executing

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (OpenShift Container Platform 4.6 GA Images), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2020:4196