Bug 1748073

Summary: Kubelet metrics returned HTTP status 500 Internal Server Error
Product: OpenShift Container Platform Reporter: Florin Peter <florin-alexandru.peter>
Component: NodeAssignee: Ryan Phillips <rphillips>
Status: CLOSED ERRATA QA Contact: Sunil Choudhary <schoudha>
Severity: medium Docs Contact:
Priority: medium    
Version: 4.2.0CC: aos-bugs, chancez, cmarches, dcaldwel, dkiselev, gblomqui, jokerman, juzhao, kechung, mpatel, rphillips, schoudha
Target Milestone: ---   
Target Release: 4.4.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Cause: Sometimes the Kubelet metrics endpoint would return a 500 status code. Consequence: This would not allow prometheus to monitor the kubelet endpoint and node for metrics. Fix: Dead containers could be mixed into the metrics stream causing duplicate metrics to be injected. These duplicate metrics would cause a 500. Result: Metrics will be reported correctly from the Kubelet.
Story Points: ---
Clone Of:
: 1779285 1781258 (view as bug list) Environment:
Last Closed: 2020-05-04 11:13:32 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1779285, 1781258, 1781281, 1781285    

Description Florin Peter 2019-09-02 16:23:49 UTC
Description of problem:
Kubelet /metrics server returned HTTP status 500 Internal Server Error maybe a dupe of 1712645.

Version-Release number of selected component (if applicable):
4.2.0-0.nightly-2019-08-27-072819

How reproducible:
not sure right now

Steps to Reproduce:
1.
2.
3.

Actual results:
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: I0902 16:11:38.009572    1360 server.go:828] GET /metrics: (3.528117ms) 500
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: goroutine 2333794 [running]:
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: github.com/openshift/origin/vendor/k8s.io/apiserver/pkg/server/httplog.(*respLogger).recordStatus(0xc001ff6fc0, 0x1f4)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /builddir/build/BUILD/openshift-git-0.b985ea3/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/apiserver/pkg/server/httplog/httplog.go:204 +0xc8
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: github.com/openshift/origin/vendor/k8s.io/apiserver/pkg/server/httplog.(*respLogger).WriteHeader(0xc001ff6fc0, 0x1f4)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /builddir/build/BUILD/openshift-git-0.b985ea3/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/apiserver/pkg/server/httplog/httplog.go:183 +0x35
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus.(*responseWriterDelegator).WriteHeader(0xc001f471a0, 0x1f4)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /builddir/build/BUILD/openshift-git-0.b985ea3/_output/local/go/src/github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus/http.go:317 +0x45
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: net/http.Error(0x944a860, 0xc001f471a0, 0xc000c5a600, 0x180, 0x1f4)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /usr/lib/golang/src/net/http/server.go:2007 +0x213
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus.httpError(0x944a860, 0xc001f471a0, 0x93b2320, 0xc00117ae40)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /builddir/build/BUILD/openshift-git-0.b985ea3/_output/local/go/src/github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus/http.go:499 +0xf3
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus.UninstrumentedHandler.func1(0x944a860, 0xc001f471a0, 0xc0016b4900)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /builddir/build/BUILD/openshift-git-0.b985ea3/_output/local/go/src/github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus/http.go:66 +0x4e5
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: net/http.HandlerFunc.ServeHTTP(0x619f220, 0x944a860, 0xc001f471a0, 0xc0016b4900)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /usr/lib/golang/src/net/http/server.go:1995 +0x44
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus.InstrumentHandlerFuncWithOpts.func1(0x9456ce0, 0xc001ff6fc0, 0xc0016b4900)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /builddir/build/BUILD/openshift-git-0.b985ea3/_output/local/go/src/github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus/http.go:260 +0x232
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: net/http.HandlerFunc.ServeHTTP(0xc0007b9c70, 0x9456ce0, 0xc001ff6fc0, 0xc0016b4900)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /usr/lib/golang/src/net/http/server.go:1995 +0x44
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: github.com/openshift/origin/vendor/github.com/emicklei/go-restful.(*Container).HandleWithFilter.func1.1(0xc001f47110, 0xc0037fec60)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /builddir/build/BUILD/openshift-git-0.b985ea3/_output/local/go/src/github.com/openshift/origin/vendor/github.com/emicklei/go-restful/container.go:311 +0x4a
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: github.com/openshift/origin/vendor/github.com/emicklei/go-restful.(*FilterChain).ProcessFilter(0xc001f470b0, 0xc001f47110, 0xc0037fec60)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /builddir/build/BUILD/openshift-git-0.b985ea3/_output/local/go/src/github.com/openshift/origin/vendor/github.com/emicklei/go-restful/filter.go:21 +0x84
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/kubelet/server.(*Server).InstallAuthFilter.func1(0xc001f47110, 0xc0037fec60, 0xc001f470b0)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /builddir/build/BUILD/openshift-git-0.b985ea3/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/kubelet/server/server.go:277 +0x52f
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: github.com/openshift/origin/vendor/github.com/emicklei/go-restful.(*FilterChain).ProcessFilter(0xc001f470b0, 0xc001f47110, 0xc0037fec60)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /builddir/build/BUILD/openshift-git-0.b985ea3/_output/local/go/src/github.com/openshift/origin/vendor/github.com/emicklei/go-restful/filter.go:19 +0x5e
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: github.com/openshift/origin/vendor/github.com/emicklei/go-restful.(*Container).HandleWithFilter.func1(0x9456ce0, 0xc001ff6fc0, 0xc0016b4900)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /builddir/build/BUILD/openshift-git-0.b985ea3/_output/local/go/src/github.com/openshift/origin/vendor/github.com/emicklei/go-restful/container.go:313 +0x285
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: net/http.HandlerFunc.ServeHTTP(0xc000a34640, 0x9456ce0, 0xc001ff6fc0, 0xc0016b4900)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /usr/lib/golang/src/net/http/server.go:1995 +0x44
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: net/http.(*ServeMux).ServeHTTP(0xc000776680, 0x9456ce0, 0xc001ff6fc0, 0xc0016b4900)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /usr/lib/golang/src/net/http/server.go:2375 +0x1d6
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: github.com/openshift/origin/vendor/github.com/emicklei/go-restful.(*Container).ServeHTTP(0xc0009717a0, 0x9456ce0, 0xc001ff6fc0, 0xc0016b4900)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /builddir/build/BUILD/openshift-git-0.b985ea3/_output/local/go/src/github.com/openshift/origin/vendor/github.com/emicklei/go-restful/container.go:292 +0x4d
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/kubelet/server.(*Server).ServeHTTP(0xc0007b8fa0, 0x9456ce0, 0xc001ff6fc0, 0xc0016b4900)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /builddir/build/BUILD/openshift-git-0.b985ea3/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/kubelet/server/server.go:827 +0x107
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: net/http.serverHandler.ServeHTTP(0xc000ebcc30, 0x945d3a0, 0xc000f3ad20, 0xc0016b4900)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /usr/lib/golang/src/net/http/server.go:2774 +0xa8
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: net/http.(*conn).serve(0xc003d88140, 0x94a21a0, 0xc001c296c0)
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /usr/lib/golang/src/net/http/server.go:1878 +0x851
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: created by net/http.(*Server).Serve
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]:         /usr/lib/golang/src/net/http/server.go:2884 +0x2f4
Sep 02 16:11:38 t420-cqp8f-worker-s2large4-eu-de-01-dtns2 hyperkube[1360]: logging error output: "An error has occurred while serving metrics:\n\ncollected metric \"kubelet_container_log_filesystem_used_bytes\" { label:<name:\"container\" value:\"fluentd\" > label:<name:\"namespace\" value:\"mcs-logging\" > label:<name:\"pod\" value:\"fluentd-qfchr\" > label:<name:\"uid\" value:\"e0cd033b-cb3d-11e9-8239-fa163e4547b3\" > gauge:<value:4096 > } was collected before with the same name and label values\n"

Expected results:
That the kubelet is not crashing 

Additional info:

Comment 1 Ryan Phillips 2019-09-03 18:32:04 UTC
Can you run `oc get pods -n mcs-logging`? Thank you!

Comment 2 Florin Peter 2019-09-03 19:03:52 UTC
Hey Ryan,

here is the output:

NAME            READY   STATUS    RESTARTS   AGE
fluentd-2whlb   1/1     Running   7          4d3h
fluentd-2xpsv   1/1     Running   7          4d3h
fluentd-9jq8t   1/1     Running   7          4d3h
fluentd-f25rn   1/1     Running   7          4d3h
fluentd-gmq9t   1/1     Running   7          4d3h
fluentd-qfchr   1/1     Running   7          4d3h
fluentd-rbkzz   1/1     Running   7          4d3h
fluentd-rhhqs   1/1     Running   7          4d3h
fluentd-xxqjv   1/1     Running   7          4d3h

Comment 3 Ryan Phillips 2019-09-04 13:31:16 UTC
Pretty sure I found the problem. Waiting on an upstream review.

Upstream PR: https://github.com/kubernetes/kubernetes/pull/82294

Comment 4 Seth Jennings 2019-09-04 18:25:54 UTC
Deferring to 4.3.  Will look to backport to 4.2.z.

Comment 5 Ryan Phillips 2019-09-05 14:00:58 UTC
*** Bug 1749149 has been marked as a duplicate of this bug. ***

Comment 6 Seth Jennings 2019-09-06 13:27:22 UTC
*** Bug 1749690 has been marked as a duplicate of this bug. ***

Comment 7 Ryan Phillips 2019-09-10 21:27:39 UTC
*** Bug 1750963 has been marked as a duplicate of this bug. ***

Comment 8 Kevin Chung 2019-11-13 19:48:34 UTC
I am also reporting this issue in my OCP 4.2 cluster, my operators are updated to 4.2.2 at the moment.  My Prometheus targets show the openshift-monitoring/kubelet/0 endpoints for /metrics are all down with a "server returned HTTP status 500 Internal Server Error".  When I dig in a little deeper, I also receive the same metrics error reported above.

Steps to reproduce:
# curl -k -H "Authorization: Bearer $(oc sa get-token prometheus-k8s -n openshift-monitoring)" https://<my-node-ip>:10250/metrics

Actual results:

An error has occurred while serving metrics:

collected metric "kubelet_container_log_filesystem_used_bytes" { label:<name:"container" value:"tuned" > label:<name:"namespace" value:"openshift-cluster-node-tuning-operator" > label:<name:"pod" value:"tuned-vpnfx" > label:<name:"uid" value:"8c78bf14-fbe6-11e9-a817-566f9e110060" > gauge:<value:36864 > } was collected before with the same name and label values

Comment 11 Ryan Phillips 2019-12-04 22:41:57 UTC
Florin: What sort of platform is this on? Is chrony or ntp running on the nodes?

Comment 12 Ryan Phillips 2019-12-05 01:18:48 UTC
Florin: Was this cluster ever suspended and resumed?

I have found some code in the kubelet that is sensitive to timestamp ordering with multiple containers within a pod.

Comment 13 Florin Peter 2019-12-06 00:58:32 UTC
Ryan: The cluster was build on OpenStack and version 4.2.2

The errors started again to target some of our clusters and this brings also our masters to flapping around.
It could be that we faced some network issues that blocked to the communication between masters but we did not suspended and resumed the clusters.

Looks like chrony is running:
ps xua | grep chrony
chrony     1023  0.0  0.0 121328  3248 ?        S    00:19   0:00 /usr/sbin/chronyd
root     123591  0.0  0.0  12764  1096 pts/0    S+   00:56   0:00 grep --color=auto chrony

Is there a workaround that we can use to stabilize the situation?

Here is the stackstrace from log
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: I1206 00:45:05.407884    2148 httplog.go:90] GET /metrics: (12.860388ms) 500
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: goroutine 1601 [running]:
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: github.com/openshift/origin/vendor/k8s.io/apiserver/pkg/server/httplog.(*respLogger).recordStatus(0xc002b8c8c0, 0x1f4)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /builddir/build/BUILD/openshift-git-0.7e13ab9/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/apiserver/pkg/server/httplog/httplog.go:217 +0xc8
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: github.com/openshift/origin/vendor/k8s.io/apiserver/pkg/server/httplog.(*respLogger).WriteHeader(0xc002b8c8c0, 0x1f4)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /builddir/build/BUILD/openshift-git-0.7e13ab9/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/apiserver/pkg/server/httplog/httplog.go:196 +0x35
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus.(*responseWriterDelegator).WriteHeader(0xc00394cff0, 0x1f4)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /builddir/build/BUILD/openshift-git-0.7e13ab9/_output/local/go/src/github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus/http.go:317 +0x45
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: net/http.Error(0x9464740, 0xc00394cff0, 0xc000a78680, 0x198, 0x1f4)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /usr/lib/golang/src/net/http/server.go:2007 +0x213
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus.httpError(0x9464740, 0xc00394cff0, 0x93cb1e0, 0xc00276c5c0)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /builddir/build/BUILD/openshift-git-0.7e13ab9/_output/local/go/src/github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus/http.go:499 +0xf3
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus.UninstrumentedHandler.func1(0x9464740, 0xc00394cff0, 0xc001639100)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /builddir/build/BUILD/openshift-git-0.7e13ab9/_output/local/go/src/github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus/http.go:66 +0x4e5
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: net/http.HandlerFunc.ServeHTTP(0x61c18c0, 0x9464740, 0xc00394cff0, 0xc001639100)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /usr/lib/golang/src/net/http/server.go:1995 +0x44
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus.InstrumentHandlerFuncWithOpts.func1(0x9470c40, 0xc002b8c8c0, 0xc001639100)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /builddir/build/BUILD/openshift-git-0.7e13ab9/_output/local/go/src/github.com/openshift/origin/vendor/github.com/prometheus/client_golang/prometheus/http.go:260 +0x232
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: net/http.HandlerFunc.ServeHTTP(0xc000509b30, 0x9470c40, 0xc002b8c8c0, 0xc001639100)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /usr/lib/golang/src/net/http/server.go:1995 +0x44
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: github.com/openshift/origin/vendor/github.com/emicklei/go-restful.(*Container).HandleWithFilter.func1.1(0xc002d62570, 0xc00278f860)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /builddir/build/BUILD/openshift-git-0.7e13ab9/_output/local/go/src/github.com/openshift/origin/vendor/github.com/emicklei/go-restful/container.go:311 +0x4a
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: github.com/openshift/origin/vendor/github.com/emicklei/go-restful.(*FilterChain).ProcessFilter(0xc002d62510, 0xc002d62570, 0xc00278f860)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /builddir/build/BUILD/openshift-git-0.7e13ab9/_output/local/go/src/github.com/openshift/origin/vendor/github.com/emicklei/go-restful/filter.go:21 +0x84
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/kubelet/server.(*Server).InstallAuthFilter.func1(0xc002d62570, 0xc00278f860, 0xc002d62510)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /builddir/build/BUILD/openshift-git-0.7e13ab9/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/kubelet/server/server.go:277 +0x52f
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: github.com/openshift/origin/vendor/github.com/emicklei/go-restful.(*FilterChain).ProcessFilter(0xc002d62510, 0xc002d62570, 0xc00278f860)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /builddir/build/BUILD/openshift-git-0.7e13ab9/_output/local/go/src/github.com/openshift/origin/vendor/github.com/emicklei/go-restful/filter.go:19 +0x5e
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: github.com/openshift/origin/vendor/github.com/emicklei/go-restful.(*Container).HandleWithFilter.func1(0x9470c40, 0xc002b8c8c0, 0xc001639100)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /builddir/build/BUILD/openshift-git-0.7e13ab9/_output/local/go/src/github.com/openshift/origin/vendor/github.com/emicklei/go-restful/container.go:313 +0x285
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: net/http.HandlerFunc.ServeHTTP(0xc00105b440, 0x9470c40, 0xc002b8c8c0, 0xc001639100)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /usr/lib/golang/src/net/http/server.go:1995 +0x44
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: net/http.(*ServeMux).ServeHTTP(0xc00060f2c0, 0x9470c40, 0xc002b8c8c0, 0xc001639100)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /usr/lib/golang/src/net/http/server.go:2375 +0x1d6
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: github.com/openshift/origin/vendor/github.com/emicklei/go-restful.(*Container).ServeHTTP(0xc000358e10, 0x9470c40, 0xc002b8c8c0, 0xc001639100)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /builddir/build/BUILD/openshift-git-0.7e13ab9/_output/local/go/src/github.com/openshift/origin/vendor/github.com/emicklei/go-restful/container.go:292 +0x4d
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: github.com/openshift/origin/vendor/k8s.io/apiserver/pkg/server/httplog.WithLogging.func1(0x94772c0, 0xc00177bb20, 0xc001639000)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /builddir/build/BUILD/openshift-git-0.7e13ab9/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/apiserver/pkg/server/httplog/httplog.go:89 +0x29c
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: net/http.HandlerFunc.ServeHTTP(0xc000fe1f60, 0x94772c0, 0xc00177bb20, 0xc001639000)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /usr/lib/golang/src/net/http/server.go:1995 +0x44
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/kubelet/server.(*Server).ServeHTTP(0xc000509090, 0x94772c0, 0xc00177bb20, 0xc001639000)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /builddir/build/BUILD/openshift-git-0.7e13ab9/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/kubelet/server/server.go:825 +0x101
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: net/http.serverHandler.ServeHTTP(0xc000f26f70, 0x94772c0, 0xc00177bb20, 0xc001639000)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /usr/lib/golang/src/net/http/server.go:2774 +0xa8
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: net/http.(*conn).serve(0xc000e9cc80, 0x94bb900, 0xc0011ad940)
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /usr/lib/golang/src/net/http/server.go:1878 +0x851
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: created by net/http.(*Server).Serve
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]:         /usr/lib/golang/src/net/http/server.go:2884 +0x2f4
Dec 06 00:45:05 p000-smq24-master-0.novalocal hyperkube[2148]: logging error output: "An error has occurred while serving metrics:\n\ncollected metric \"kubelet_container_log_filesystem_used_bytes\" { label:<name:\"container\" value:\"tuned\" > label:<name:\"namespace\" value:\"openshift-cluster-node-tuning-operator\" > label:<name:\"pod\" value:\"tuned-pf625\" > label:<name:\"uid\" value:\"8faa953a-17be-11ea-b588-fa163e803fbd\" > gauge:<value:12288 > } was collected before with the same name and label values\n"

Comment 14 Ryan Phillips 2019-12-06 23:45:43 UTC
I have good news, and I thank you for your patience. I have an upstream PR fixing the issue [1] which has been approved and in the process of merging. The issue is the Kubelet stats system can inject stopped containers into the metrics stream.

I will backport this patch into our Openshift releases on Monday.

1. https://github.com/kubernetes/kubernetes/pull/86009

Comment 15 Florin Peter 2019-12-09 10:58:35 UTC
Hey Ryan,

good work and thx for your effort!
Hope to see this getting soon backported to 4.2.

Comment 16 Ryan Phillips 2019-12-10 14:26:37 UTC
*** Bug 1774091 has been marked as a duplicate of this bug. ***

Comment 17 Sam Batschelet 2019-12-10 15:33:47 UTC
*** Bug 1759260 has been marked as a duplicate of this bug. ***

Comment 26 errata-xmlrpc 2020-05-04 11:13:32 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, 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:0581