Metrics-server: Error "pathrecorder.go:107] registered "/metrics" from goroutine 1 [running]" with stack dump

[CheyiLin]

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/[email protected]/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/[email protected]/pkg/server/mux/pathrecorder.go:173 +0x84
k8s.io/apiserver/pkg/server/routes.MetricsWithReset.Install(0xc00004c540)
    /go/pkg/mod/k8s.io/[email protected]/pkg/server/routes/metrics.go:43 +0x5d
k8s.io/apiserver/pkg/server.installAPI(0xc00000a1e0, 0xc0004a0d80)
    /go/pkg/mod/k8s.io/[email protected]/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/[email protected]/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/[email protected]/command.go:842 +0x453
github.com/spf13/cobra.(*Command).ExecuteC(0xc000306000, 0xc0000c4120, 0x0, 0x0)
    /go/pkg/mod/github.com/spf13/[email protected]/command.go:950 +0x349
github.com/spf13/cobra.(*Command).Execute(...)
    /go/pkg/mod/github.com/spf13/[email protected]/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/[email protected]/tools/cache/reflector.go:156
I1109 09:23:56.870791       1 reflector.go:243] Listing and watching *v1.Pod from pkg/mod/k8s.io/[email protected]/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/[email protected]/tools/cache/reflector.go:156
I1109 09:23:56.871613       1 reflector.go:243] Listing and watching *v1.Node from pkg/mod/k8s.io/[email protected]/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

[ronaldploeger]

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/[email protected]/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/[email protected]/pkg/server/mux/pathrecorder.go:173 +0x84
k8s.io/apiserver/pkg/server/routes.MetricsWithReset.Install(0xc000284770)
    /go/pkg/mod/k8s.io/[email protected]/pkg/server/routes/metrics.go:43 +0x5d
k8s.io/apiserver/pkg/server.installAPI(0xc00000a1e0, 0xc0000bc000)
    /go/pkg/mod/k8s.io/[email protected]/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/[email protected]/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/[email protected]/command.go:842 +0x453
github.com/spf13/cobra.(*Command).ExecuteC(0xc00043f340, 0xc00012a120, 0x0, 0x0)
    /go/pkg/mod/github.com/spf13/[email protected]/command.go:950 +0x349
github.com/spf13/cobra.(*Command).Execute(...)
    /go/pkg/mod/github.com/spf13/[email protected]/command.go:887
main.main()
    /go/src/sigs.k8s.io/metrics-server/cmd/metrics-server/metrics-server.go:38 +0xae

[serathius]

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]

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