Bug 1949721 - Pick 99237: Use the audit ID of a request for better correlation
Summary: Pick 99237: Use the audit ID of a request for better correlation
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: kube-apiserver
Version: 4.8
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: ---
: 4.8.0
Assignee: Abu Kashem
QA Contact: Ke Wang
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-04-14 22:12 UTC by Abu Kashem
Modified: 2021-07-27 23:01 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2021-07-27 23:00:57 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github openshift kubernetes pull 672 0 None open Bug 1949721: UPSTREAM: 99237: Use the audit ID of a request for better correlation 2021-04-14 22:14:02 UTC
Red Hat Product Errata RHSA-2021:2438 0 None None None 2021-07-27 23:01:18 UTC

Description Abu Kashem 2021-04-14 22:12:54 UTC
Use the audit ID of a request for better correlation
Pick https://github.com/kubernetes/kubernetes/pull/99237

Comment 2 Ke Wang 2021-04-20 11:34:35 UTC
$ oc get clusterversion
NAME      VERSION                             AVAILABLE   PROGRESSING   SINCE   STATUS
version   4.8.0-0.nightly-2021-04-19-225513   True        False         160m    Cluster version is 4.8.0-0.nightly-2021-04-19-225513

$ oc edit kubeapiserver/cluster # change log level from Normal to TraceAll and waiting for the kube-apiserber restart to complete.

$ oc logs -n openshift-kube-apiserver kube-apiserver-ip-10-0-143-111.us-east-2.compute.internal -c kube-apiserver > kas.log

Searching the Audit-Id in kas.log,
$ grep -n Audit-Id kube-apiserver.log 
1388:I0420 09:27:23.664452      18 round_trippers.go:463]     Audit-Id: 4cd4b91e-d364-4b70-bb4a-685ecd02081d
1485:I0420 09:27:23.676630      18 round_trippers.go:463]     Audit-Id: 1ce6df5b-50d0-4813-9bcd-6802e714fd87
1495:I0420 09:27:23.677541      18 round_trippers.go:463]     Audit-Id: c62dc3be-6ad6-4378-9bc7-01e74fadf43d
...

Selected one Audit-Id eb3f149b-5ac8-4e4d-b61e-254a2b772492 and check the relevant logs,
...
I0420 06:59:45.686939      19 handler.go:153] kube-aggregator: GET "/apis/user.openshift.io/v1/users/~" satisfied by nonGoRestful
I0420 06:59:45.686954      19 pathrecorder.go:247] kube-aggregator: "/apis/user.openshift.io/v1/users/~" satisfied by prefix /apis/user.openshift.io/v1/
I0420 06:59:45.686988      19 upgradeaware.go:270] Request was not an upgrade
I0420 06:59:45.687041      19 round_trippers.go:432] GET https://10.128.0.25:8443/apis/user.openshift.io/v1/users/~
I0420 06:59:45.687054      19 round_trippers.go:438] Request Headers:
I0420 06:59:45.687061      19 round_trippers.go:442]     X-Forwarded-For: 10.0.212.114
I0420 06:59:45.687067      19 round_trippers.go:442]     X-Forwarded-Uri: /apis/user.openshift.io/v1/users/~
I0420 06:59:45.687072      19 round_trippers.go:442]     X-Forwarded-Host: 10.128.0.25:8443
I0420 06:59:45.687076      19 round_trippers.go:442]     X-Forwarded-Proto: https
I0420 06:59:45.687080      19 round_trippers.go:442]     User-Agent: dockerregistry/v0.0.0 (linux/amd64) kubernetes/$Format
I0420 06:59:45.687084      19 round_trippers.go:442]     Accept-Encoding: gzip
I0420 06:59:45.687088      19 round_trippers.go:442]     Accept: application/json, */*
I0420 06:59:45.687092      19 round_trippers.go:442]     Audit-Id: eb3f149b-5ac8-4e4d-b61e-254a2b772492
I0420 06:59:45.687096      19 round_trippers.go:442]     X-Remote-User: system:serviceaccount:openshift-monitoring:prometheus-k8s
I0420 06:59:45.687100      19 round_trippers.go:442]     X-Remote-Group: system:serviceaccounts
I0420 06:59:45.687104      19 round_trippers.go:442]     X-Remote-Group: system:serviceaccounts:openshift-monitoring
I0420 06:59:45.687108      19 round_trippers.go:442]     X-Remote-Group: system:authenticated
I0420 06:59:45.697917      19 round_trippers.go:457] Response Status: 200 OK in 10 milliseconds
I0420 06:59:45.697946      19 round_trippers.go:460] Response Headers:
I0420 06:59:45.697953      19 round_trippers.go:463]     Content-Type: application/json
I0420 06:59:45.697957      19 round_trippers.go:463]     X-Kubernetes-Pf-Flowschema-Uid: ef4d4f02-9c20-4967-a243-fe03abfae1ba
I0420 06:59:45.697960      19 round_trippers.go:463]     X-Kubernetes-Pf-Prioritylevel-Uid: 8b6be9a3-39a8-4d71-b86b-965fa88015a5
I0420 06:59:45.697963      19 round_trippers.go:463]     Content-Length: 262
I0420 06:59:45.697968      19 round_trippers.go:463]     Date: Tue, 20 Apr 2021 06:59:45 GMT
I0420 06:59:45.697973      19 round_trippers.go:463]     Audit-Id: eb3f149b-5ac8-4e4d-b61e-254a2b772492
I0420 06:59:45.697977      19 round_trippers.go:463]     Cache-Control: no-cache, private
...
I0420 06:59:45.698299      19 httplog.go:101] "HTTP" verb="GET" URI="/apis/user.openshift.io/v1/users/~" latency="12.271185ms" userAgent="dockerregistry/v0.0.0 (linux/amd64) kubernetes/$Format" audit-ID="eb3f149b-5ac8-4e4d-b61e-254a2b772492" srcIP="10.0.212.114:49550" resp=200
...
I0420 07:00:26.224282      19 apf_filter.go:160] Handle(RequestDigest{RequestInfo: &request.RequestInfo{IsResourceRequest:true, Path:"/apis/discovery.k8s.io/v1/namespaces/default/endpointslices/kubernetes", Verb:"get", APIPrefix:"apis", APIGroup:"discovery.k8s.io", APIVersion:"v1", Namespace:"default", Resource:"endpointslices", Subresource:"", Name:"kubernetes", Parts:[]string{"endpointslices", "kubernetes"}}, User: &user.DefaultInfo{Name:"system:apiserver", UID:"10cc31b6-1075-4dd6-89ae-df8978352f89", Groups:[]string{"system:masters"}, Extra:map[string][]string(nil)}}) => fsName="exempt", distMethod=(*v1beta1.FlowDistinguisherMethod)(nil), plName="exempt", isExempt=true, queued=false, Finish() => panicking=false idle=false
I0420 07:00:26.224431      19 httplog.go:101] "HTTP" verb="GET" URI="/apis/discovery.k8s.io/v1/namespaces/default/endpointslices/kubernetes" latency="7.633118ms" userAgent="kube-apiserver/v1.21.0 (linux/amd64) kubernetes/98d91ef" audit-ID="553f952b-4a17-4117-b769-0986f6ad47b7" srcIP="[::1]:51598" resp=200
I0420 07:00:26.225503      19 round_trippers.go:457] Response Status: 200 OK in 8 milliseconds
I0420 07:00:26.225521      19 round_trippers.go:460] Response Headers:
I0420 07:00:26.225527      19 round_trippers.go:463]     X-Kubernetes-Pf-Flowschema-Uid: 8e8569e6-d968-4f2e-b6a3-229af588d9c1
I0420 07:00:26.225532      19 round_trippers.go:463]     X-Kubernetes-Pf-Prioritylevel-Uid: 39f9e445-d2f6-4608-a4fb-074010f3e214
I0420 07:00:26.225537      19 round_trippers.go:463]     Content-Length: 452
I0420 07:00:26.225542      19 round_trippers.go:463]     Date: Tue, 20 Apr 2021 07:00:26 GMT
I0420 07:00:26.225548      19 round_trippers.go:463]     Audit-Id: 553f952b-4a17-4117-b769-0986f6ad47b7
I0420 07:00:26.225552      19 round_trippers.go:463]     Cache-Control: no-cache, private
I0420 07:00:26.225558      19 round_trippers.go:463]     Content-Type: application/vnd.kubernetes.protobuf
...
From above, we can see the same Audit ID is in Request/Response headers and used in httplog, audit ID of a request gets better correlation, works as expected, so move the bug VERIFIED.

Comment 5 errata-xmlrpc 2021-07-27 23:00:57 UTC
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 (Moderate: OpenShift Container Platform 4.8.2 bug fix and security update), 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/RHSA-2021:2438


Note You need to log in before you can comment on or make changes to this bug.