Error "pathrecorder.go:107] registered "/metrics" from goroutine 1 [running]" with stack dump #630

CheyiLin · 2020-11-09T09:41:25Z

What happened:
metrics-server v0.4.0 starts with error pathrecorder.go:107] registered "/metrics" from goroutine 1 [running] and stack dump. But it seems working as normal.

What you expected to happen:
No error.

Anything else we need to know?:
No.

Environment:

Kubernetes distribution:
Kubernetes 1.17.13, created by kops on AWS
Container Network Setup:
calico with cross-subnet mode enabled
Kubernetes version:

Client Version: version.Info{Major:"1", Minor:"17", GitVersion:"v1.17.13", GitCommit:"30d651da517185653e34e7ab99a792be6a3d9495", GitTreeState:"clean", BuildDate:"2020-10-15T01:06:31Z", GoVersion:"go1.13.15", Compiler:"gc", Platform:"darwin/amd64"}
Server Version: version.Info{Major:"1", Minor:"17", GitVersion:"v1.17.13", GitCommit:"30d651da517185653e34e7ab99a792be6a3d9495", GitTreeState:"clean", BuildDate:"2020-10-15T00:59:17Z", GoVersion:"go1.13.15", Compiler:"gc", Platform:"linux/amd64"}

Metrics Server manifest

spoiler for Metrics Server manifest:

---
apiVersion: v1
kind: ServiceAccount
metadata:
  labels:
    k8s-app: metrics-server
  name: metrics-server
  namespace: kube-system

---
apiVersion: rbac.authorization.k8s.io/v1
kind: ClusterRole
metadata:
  labels:
    k8s-app: metrics-server
    rbac.authorization.k8s.io/aggregate-to-admin: "true"
    rbac.authorization.k8s.io/aggregate-to-edit: "true"
    rbac.authorization.k8s.io/aggregate-to-view: "true"
  name: system:aggregated-metrics-reader
rules:
- apiGroups:
  - metrics.k8s.io
  resources:
  - pods
  - nodes
  verbs:
  - get
  - list
  - watch

---
apiVersion: rbac.authorization.k8s.io/v1
kind: ClusterRole
metadata:
  labels:
    k8s-app: metrics-server
  name: system:metrics-server
rules:
- apiGroups:
  - ""
  resources:
  - pods
  - nodes
  - nodes/stats
  - namespaces
  - configmaps
  verbs:
  - get
  - list
  - watch

---
apiVersion: rbac.authorization.k8s.io/v1
kind: RoleBinding
metadata:
  labels:
    k8s-app: metrics-server
  name: metrics-server-auth-reader
  namespace: kube-system
roleRef:
  apiGroup: rbac.authorization.k8s.io
  kind: Role
  name: extension-apiserver-authentication-reader
subjects:
- kind: ServiceAccount
  name: metrics-server
  namespace: kube-system

---
apiVersion: rbac.authorization.k8s.io/v1
kind: ClusterRoleBinding
metadata:
  labels:
    k8s-app: metrics-server
  name: metrics-server:system:auth-delegator
roleRef:
  apiGroup: rbac.authorization.k8s.io
  kind: ClusterRole
  name: system:auth-delegator
subjects:
- kind: ServiceAccount
  name: metrics-server
  namespace: kube-system

---
apiVersion: rbac.authorization.k8s.io/v1
kind: ClusterRoleBinding
metadata:
  labels:
    k8s-app: metrics-server
  name: system:metrics-server
roleRef:
  apiGroup: rbac.authorization.k8s.io
  kind: ClusterRole
  name: system:metrics-server
subjects:
- kind: ServiceAccount
  name: metrics-server
  namespace: kube-system

---
apiVersion: v1
kind: Service
metadata:
  labels:
    k8s-app: metrics-server
  name: metrics-server
  namespace: kube-system
spec:
  ports:
  - name: https
    port: 443
    protocol: TCP
    targetPort: https
  selector:
    k8s-app: metrics-server

---
apiVersion: apps/v1
kind: Deployment
metadata:
  labels:
    k8s-app: metrics-server
  name: metrics-server
  namespace: kube-system
spec:
  selector:
    matchLabels:
      k8s-app: metrics-server
  strategy:
    rollingUpdate:
      maxUnavailable: 0
  template:
    metadata:
      labels:
        k8s-app: metrics-server
    spec:
      containers:
      - args:
        - --cert-dir=/tmp
        - --secure-port=4443
        - --kubelet-preferred-address-types=InternalIP,ExternalIP,Hostname
        - --kubelet-use-node-status-port
        - --kubelet-insecure-tls
        - --v=7
        image: k8s.gcr.io/metrics-server/metrics-server:v0.4.0
        imagePullPolicy: IfNotPresent
        livenessProbe:
          failureThreshold: 3
          httpGet:
            path: /livez
            port: https
            scheme: HTTPS
          periodSeconds: 10
        name: metrics-server
        ports:
        - containerPort: 4443
          name: https
          protocol: TCP
        readinessProbe:
          failureThreshold: 3
          httpGet:
            path: /readyz
            port: https
            scheme: HTTPS
          periodSeconds: 10
        securityContext:
          readOnlyRootFilesystem: true
          runAsNonRoot: true
          runAsUser: 1000
        volumeMounts:
        - mountPath: /tmp
          name: tmp-dir
      tolerations:
        - key: node-role.kubernetes.io/master
          operator: Exists
          effect: NoSchedule
      nodeSelector:
        kubernetes.io/os: linux
        kubernetes.io/role: master
      priorityClassName: system-cluster-critical
      serviceAccountName: metrics-server
      volumes:
      - emptyDir: {}
        name: tmp-dir

---
apiVersion: apiregistration.k8s.io/v1
kind: APIService
metadata:
  labels:
    k8s-app: metrics-server
  name: v1beta1.metrics.k8s.io
spec:
  group: metrics.k8s.io
  groupPriorityMinimum: 100
  insecureSkipTLSVerify: true
  service:
    name: metrics-server
    namespace: kube-system
  version: v1beta1
  versionPriority: 100

Kubelet config:

spoiler for Kubelet config:

{
  "kubeletconfig": {
    "staticPodPath": "/etc/kubernetes/manifests",
    "syncFrequency": "1m0s",
    "fileCheckFrequency": "20s",
    "httpCheckFrequency": "20s",
    "address": "0.0.0.0",
    "port": 10250,
    "readOnlyPort": 10255,
    "tlsCertFile": "/var/lib/kubelet/pki/kubelet.crt",
    "tlsPrivateKeyFile": "/var/lib/kubelet/pki/kubelet.key",
    "authentication": {
      "x509": {
        "clientCAFile": "/srv/kubernetes/ca.crt"
      },
      "webhook": {
        "enabled": true,
        "cacheTTL": "2m0s"
      },
      "anonymous": {
        "enabled": false
      }
    },
    "authorization": {
      "mode": "Webhook",
      "webhook": {
        "cacheAuthorizedTTL": "5m0s",
        "cacheUnauthorizedTTL": "30s"
      }
    },
    "registryPullQPS": 5,
    "registryBurst": 10,
    "eventRecordQPS": 5,
    "eventBurst": 10,
    "enableDebuggingHandlers": true,
    "healthzPort": 10248,
    "healthzBindAddress": "127.0.0.1",
    "oomScoreAdj": -999,
    "clusterDomain": "cluster.local",
    "clusterDNS": [
      "169.254.20.10"
    ],
    "streamingConnectionIdleTimeout": "4h0m0s",
    "nodeStatusUpdateFrequency": "10s",
    "nodeStatusReportFrequency": "5m0s",
    "nodeLeaseDurationSeconds": 40,
    "imageMinimumGCAge": "2m0s",
    "imageGCHighThresholdPercent": 85,
    "imageGCLowThresholdPercent": 80,
    "volumeStatsAggPeriod": "1m0s",
    "cgroupRoot": "/",
    "cgroupsPerQOS": true,
    "cgroupDriver": "cgroupfs",
    "cpuManagerPolicy": "none",
    "cpuManagerReconcilePeriod": "10s",
    "topologyManagerPolicy": "none",
    "runtimeRequestTimeout": "2m0s",
    "hairpinMode": "promiscuous-bridge",
    "maxPods": 110,
    "podPidsLimit": -1,
    "resolvConf": "/etc/resolv.conf",
    "cpuCFSQuota": true,
    "cpuCFSQuotaPeriod": "100ms",
    "maxOpenFiles": 1000000,
    "contentType": "application/vnd.kubernetes.protobuf",
    "kubeAPIQPS": 5,
    "kubeAPIBurst": 10,
    "serializeImagePulls": true,
    "evictionHard": {
      "imagefs.available": "10%",
      "imagefs.inodesFree": "5%",
      "memory.available": "100Mi",
      "nodefs.available": "10%",
      "nodefs.inodesFree": "5%"
    },
    "evictionPressureTransitionPeriod": "5m0s",
    "enableControllerAttachDetach": true,
    "makeIPTablesUtilChains": true,
    "iptablesMasqueradeBit": 14,
    "iptablesDropBit": 15,
    "failSwapOn": true,
    "containerLogMaxSize": "10Mi",
    "containerLogMaxFiles": 5,
    "configMapAndSecretChangeDetectionStrategy": "Watch",
    "systemReserved": {
      "cpu": "100m",
      "ephemeral-storage": "1Gi",
      "memory": "200Mi"
    },
    "kubeReserved": {
      "cpu": "100m",
      "ephemeral-storage": "1Gi",
      "memory": "200Mi"
    },
    "enforceNodeAllocatable": [
      "pods"
    ]
  }
}

Metrics server logs:

spoiler for Metrics Server logs:

I1109 09:23:55.768068       1 serving.go:325] Generated self-signed cert (/tmp/apiserver.crt, /tmp/apiserver.key)
I1109 09:23:55.768956       1 dynamic_serving_content.go:111] Loaded a new cert/key pair for "serving-cert::/tmp/apiserver.crt::/tmp/apiserver.key"
I1109 09:23:56.837744       1 round_trippers.go:420] GET https://100.64.0.1:443/api/v1/namespaces/kube-system/configmaps/extension-apiserver-authentication
I1109 09:23:56.837776       1 round_trippers.go:427] Request Headers:
I1109 09:23:56.837787       1 round_trippers.go:431]     Authorization: Bearer <masked>
I1109 09:23:56.838234       1 round_trippers.go:431]     Accept: application/json, */*
I1109 09:23:56.838260       1 round_trippers.go:431]     User-Agent: metrics-server/v0.0.0 (linux/amd64) kubernetes/$Format
I1109 09:23:56.846003       1 round_trippers.go:446] Response Status: 200 OK in 7 milliseconds
I1109 09:23:56.847026       1 requestheader_controller.go:244] Loaded a new request header values for RequestHeaderAuthRequestController
I1109 09:23:56.858319       1 config.go:638] Not requested to run hook priority-and-fairness-config-consumer
E1109 09:23:56.860879       1 pathrecorder.go:107] registered "/metrics" from goroutine 1 [running]:
runtime/debug.Stack(0x1942e80, 0xc000742c60, 0x1bb58b5)
	/usr/local/go/src/runtime/debug/stack.go:24 +0x9d
k8s.io/apiserver/pkg/server/mux.(*PathRecorderMux).trackCallers(0xc00004c540, 0x1bb58b5, 0x8)
	/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/mux/pathrecorder.go:109 +0x86
k8s.io/apiserver/pkg/server/mux.(*PathRecorderMux).Handle(0xc00004c540, 0x1bb58b5, 0x8, 0x1e96f00, 0xc000824660)
	/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/mux/pathrecorder.go:173 +0x84
k8s.io/apiserver/pkg/server/routes.MetricsWithReset.Install(0xc00004c540)
	/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/routes/metrics.go:43 +0x5d
k8s.io/apiserver/pkg/server.installAPI(0xc00000a1e0, 0xc0004a0d80)
	/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/config.go:711 +0x6c
k8s.io/apiserver/pkg/server.completedConfig.New(0xc0004a0d80, 0x1f099c0, 0xc000746140, 0x1bbdb5a, 0xe, 0x1ef29e0, 0x2cef248, 0x0, 0x0, 0x0)
	/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/config.go:657 +0xb45
sigs.k8s.io/metrics-server/pkg/server.Config.Complete(0xc0004a0d80, 0xc00049f200, 0xc000498000, 0xdf8475800, 0xc92a69c00, 0x0, 0x0, 0xdf8475800)
	/go/src/sigs.k8s.io/metrics-server/pkg/server/config.go:52 +0x312
sigs.k8s.io/metrics-server/cmd/metrics-server/app.runCommand(0xc000142000, 0xc000274480, 0x0, 0x0)
	/go/src/sigs.k8s.io/metrics-server/cmd/metrics-server/app/start.go:66 +0x157
sigs.k8s.io/metrics-server/cmd/metrics-server/app.NewMetricsServerCommand.func1(0xc000306000, 0xc0001710e0, 0x0, 0x6, 0x0, 0x0)
	/go/src/sigs.k8s.io/metrics-server/cmd/metrics-server/app/start.go:37 +0x33
github.com/spf13/cobra.(*Command).execute(0xc000306000, 0xc0000ca010, 0x6, 0x6, 0xc000306000, 0xc0000ca010)
	/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:842 +0x453
github.com/spf13/cobra.(*Command).ExecuteC(0xc000306000, 0xc0000c4120, 0x0, 0x0)
	/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:950 +0x349
github.com/spf13/cobra.(*Command).Execute(...)
	/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:887
main.main()
	/go/src/sigs.k8s.io/metrics-server/cmd/metrics-server/metrics-server.go:38 +0xae
I1109 09:23:56.870756       1 reflector.go:207] Starting reflector *v1.Pod (0s) from pkg/mod/k8s.io/client-go@v0.19.2/tools/cache/reflector.go:156
I1109 09:23:56.870791       1 reflector.go:243] Listing and watching *v1.Pod from pkg/mod/k8s.io/client-go@v0.19.2/tools/cache/reflector.go:156
I1109 09:23:56.871223       1 round_trippers.go:420] GET https://100.64.0.1:443/api/v1/pods?limit=500&resourceVersion=0
I1109 09:23:56.871251       1 round_trippers.go:427] Request Headers:
I1109 09:23:56.871262       1 round_trippers.go:431]     User-Agent: metrics-server/v0.0.0 (linux/amd64) kubernetes/$Format
I1109 09:23:56.871301       1 round_trippers.go:431]     Authorization: Bearer <masked>
I1109 09:23:56.871311       1 round_trippers.go:431]     Accept: application/vnd.kubernetes.protobuf, */*
I1109 09:23:56.871596       1 reflector.go:207] Starting reflector *v1.Node (0s) from pkg/mod/k8s.io/client-go@v0.19.2/tools/cache/reflector.go:156
I1109 09:23:56.871613       1 reflector.go:243] Listing and watching *v1.Node from pkg/mod/k8s.io/client-go@v0.19.2/tools/cache/reflector.go:156
I1109 09:23:56.871718       1 round_trippers.go:420] GET https://100.64.0.1:443/api/v1/nodes?limit=500&resourceVersion=0
I1109 09:23:56.871733       1 round_trippers.go:427] Request Headers:
I1109 09:23:56.871742       1 round_trippers.go:431]     User-Agent: metrics-server/v0.0.0 (linux/amd64) kubernetes/$Format
I1109 09:23:56.871750       1 round_trippers.go:431]     Accept: application/vnd.kubernetes.protobuf, */*
I1109 09:23:56.871759       1 round_trippers.go:431]     Authorization: Bearer <masked>
I1109 09:23:56.876899       1 round_trippers.go:446] Response Status: 200 OK in 5 milliseconds
I1109 09:23:56.891667       1 round_trippers.go:446] Response Status: 200 OK in 19 milliseconds
I1109 09:23:56.900791       1 round_trippers.go:420] GET https://100.64.0.1:443/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=39252246&timeout=8m1s&timeoutSeconds=481&watch=true
I1109 09:23:56.901106       1 round_trippers.go:427] Request Headers:
I1109 09:23:56.901235       1 round_trippers.go:431]     Accept: application/vnd.kubernetes.protobuf, */*
I1109 09:23:56.901350       1 round_trippers.go:431]     User-Agent: metrics-server/v0.0.0 (linux/amd64) kubernetes/$Format
I1109 09:23:56.901479       1 round_trippers.go:431]     Authorization: Bearer <masked>
I1109 09:23:56.903590       1 round_trippers.go:446] Response Status: 200 OK in 1 milliseconds
...

/kind bug

The text was updated successfully, but these errors were encountered:

ronaldploeger · 2020-11-10T16:11:49Z

Same for me on AWS EKS: v1.18.9-eks-d1db3c

E1110 15:41:46.666415       1 pathrecorder.go:107] registered "/metrics" from goroutine 1 [running]:
runtime/debug.Stack(0x1942e80, 0xc000715ec0, 0x1bb58b5)
	/usr/local/go/src/runtime/debug/stack.go:24 +0x9d
k8s.io/apiserver/pkg/server/mux.(*PathRecorderMux).trackCallers(0xc000284770, 0x1bb58b5, 0x8)
	/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/mux/pathrecorder.go:109 +0x86
k8s.io/apiserver/pkg/server/mux.(*PathRecorderMux).Handle(0xc000284770, 0x1bb58b5, 0x8, 0x1e96f00, 0xc00078b5c0)
	/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/mux/pathrecorder.go:173 +0x84
k8s.io/apiserver/pkg/server/routes.MetricsWithReset.Install(0xc000284770)
	/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/routes/metrics.go:43 +0x5d
k8s.io/apiserver/pkg/server.installAPI(0xc00000a1e0, 0xc0000bc000)
	/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/config.go:711 +0x6c
k8s.io/apiserver/pkg/server.completedConfig.New(0xc0000bc000, 0x1f099c0, 0xc000667bd0, 0x1bbdb5a, 0xe, 0x1ef29e0, 0x2cef248, 0x0, 0x0, 0x0)
	/go/pkg/mod/k8s.io/apiserver@v0.19.2/pkg/server/config.go:657 +0xb45
sigs.k8s.io/metrics-server/pkg/server.Config.Complete(0xc0000bc000, 0xc0000afb00, 0xc0004a4240, 0xdf8475800, 0xc92a69c00, 0x0, 0x0, 0xdf8475800)
	/go/src/sigs.k8s.io/metrics-server/pkg/server/config.go:52 +0x312
sigs.k8s.io/metrics-server/cmd/metrics-server/app.runCommand(0xc0000fadc0, 0xc0000acba0, 0x0, 0x0)
	/go/src/sigs.k8s.io/metrics-server/cmd/metrics-server/app/start.go:66 +0x157
sigs.k8s.io/metrics-server/cmd/metrics-server/app.NewMetricsServerCommand.func1(0xc00043f340, 0xc0002c56c0, 0x0, 0x4, 0x0, 0x0)
	/go/src/sigs.k8s.io/metrics-server/cmd/metrics-server/app/start.go:37 +0x33
github.com/spf13/cobra.(*Command).execute(0xc00043f340, 0xc000100060, 0x4, 0x4, 0xc00043f340, 0xc000100060)
	/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:842 +0x453
github.com/spf13/cobra.(*Command).ExecuteC(0xc00043f340, 0xc00012a120, 0x0, 0x0)
	/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:950 +0x349
github.com/spf13/cobra.(*Command).Execute(...)
	/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:887
main.main()
	/go/src/sigs.k8s.io/metrics-server/cmd/metrics-server/metrics-server.go:38 +0xae

serathius · 2020-11-10T20:11:16Z

Reproduced in KIND cluster. Looks like this panic doesn't influence Metrics Server functions (exposing Metrics API, Prometheus metrics).

I will look into this.
/assign

serathius · 2020-11-10T22:39:40Z

Confirmed that this is totally harmless. In 0.4.0 we introduced own prometheus metrics handler, but didn't correctly disable default one. As result same path is registered twice, which is reported as error with stacktrace.

Will send fix soon

k8s-ci-robot added the kind/bug Categorizes issue or PR as related to a bug. label Nov 9, 2020

k8s-ci-robot assigned serathius Nov 10, 2020

serathius mentioned this issue Nov 10, 2020

Disable default metrics handler #634

Merged

k8s-ci-robot closed this as completed in #634 Nov 11, 2020

This was referenced Nov 12, 2020

Rebase https://github.com/kubernetes-sigs/metrics-server/pull/634 to release-0.4 #635

Merged

Latest version metrics-server failed with go coroutine error #637

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Error "pathrecorder.go:107] registered "/metrics" from goroutine 1 [running]" with stack dump #630

Error "pathrecorder.go:107] registered "/metrics" from goroutine 1 [running]" with stack dump #630

CheyiLin commented Nov 9, 2020

ronaldploeger commented Nov 10, 2020 •

edited by serathius

serathius commented Nov 10, 2020

serathius commented Nov 10, 2020

Error "pathrecorder.go:107] registered "/metrics" from goroutine 1 [running]" with stack dump #630

Error "pathrecorder.go:107] registered "/metrics" from goroutine 1 [running]" with stack dump #630

Comments

CheyiLin commented Nov 9, 2020

ronaldploeger commented Nov 10, 2020 • edited by serathius

serathius commented Nov 10, 2020

serathius commented Nov 10, 2020

ronaldploeger commented Nov 10, 2020 •

edited by serathius