search

hashicorp / vault-k8s

First-class support for Vault and Kubernetes.
Mozilla Public License 2.0
786 stars 169 forks source link

[controller-runtime] log.SetLogger(...) was never called; logs will not be displayed. #605

Closed deadlysyn closed 7 months ago

deadlysyn commented 7 months ago

Describe the bug

Updated to 1.4.0 on EKS 1.29 and several of our pods logged:

[controller-runtime] log.SetLogger(...) was never called; logs will not be displayed.
Detected at:
    >  goroutine 26 [running]:
    >  runtime/debug.Stack()
    >   /opt/hostedtoolcache/go/1.21.7/x64/src/runtime/debug/stack.go:24 +0x5e
    >  sigs.k8s.io/controller-runtime/pkg/log.eventuallyFulfillRoot()
    >   /home/runner/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.16.3/pkg/log/log.go:60 +0xcd
    >  sigs.k8s.io/controller-runtime/pkg/log.(*delegatingLogSink).Error(0xc00029dac0, {0x1d16420, 0xc0005f6640}, {0x1ab173f, 0x12}, {0xc0004b2420, 0x2, 0x2})
    >   /home/runner/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.16.3/pkg/log/deleg.go:139 +0x5d
    >  github.com/go-logr/logr.Logger.Error({{0x1d349a8?, 0xc00029dac0?}, 0xc000152280?}, {0x1d16420, 0xc0005f6640}, {0x1ab173f, 0x12}, {0xc0004b2420, 0x2, 0x2})
    >   /home/runner/go/pkg/mod/github.com/go-logr/logr@v1.3.0/logr.go:305 +0xda
    >  github.com/operator-framework/operator-lib/leader.getNode({0x1d30a20?, 0xc000152280?}, {0x1d3af00?, 0xc0001e5680?}, {0xc00082b700, 0x1c}, 0xc0001a8900?)
    >   /home/runner/go/pkg/mod/github.com/operator-framework/operator-lib@v0.12.0/leader/leader.go:276 +0x13b
    >  github.com/operator-framework/operator-lib/leader.isNotReadyNode({0x1d30a20, 0xc000152280}, {0x1d3af00, 0xc0001e5680}, {0xc00082b700, 0x1c})
    >   /home/runner/go/pkg/mod/github.com/operator-framework/operator-lib@v0.12.0/leader/leader.go:284 +0x93
    >  github.com/operator-framework/operator-lib/leader.Become({0x1d30a20, 0xc000152280}, {0x1aae52a, 0x10}, {0x0, 0x0, 0x0?})
    >   /home/runner/go/pkg/mod/github.com/operator-framework/operator-lib@v0.12.0/leader/leader.go:189 +0x8ea
    >  github.com/hashicorp/vault-k8s/leader.New.func1.1()
    >   /home/runner/work/vault-k8s/vault-k8s/leader/leader.go:44 +0x45
    >  github.com/cenkalti/backoff/v4.RetryNotifyWithTimer.Operation.withEmptyData.func1()
    >   /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:18 +0x13
    >  github.com/cenkalti/backoff/v4.doRetryNotify[...](0xc00065bf10?, {0x1d1ba28, 0xc000170020}, 0x0, {0x0, 0x0?})
    >   /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:88 +0x13c
    >  github.com/cenkalti/backoff/v4.RetryNotifyWithTimer(0x0?, {0x1d1ba28?, 0xc000170020?}, 0x0?, {0x0?, 0x0?})
    >   /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:61 +0x5c
    >  github.com/cenkalti/backoff/v4.RetryNotify(...)
    >   /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:49
    >  github.com/cenkalti/backoff/v4.Retry(...)
    >   /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:38
    >  github.com/hashicorp/vault-k8s/leader.New.func1()
    >   /home/runner/work/vault-k8s/vault-k8s/leader/leader.go:43 +0x12c
    >  created by github.com/hashicorp/vault-k8s/leader.New in goroutine 1
    >   /home/runner/work/vault-k8s/vault-k8s/leader/leader.go:31 +0xf8

appears related to https://github.com/kubernetes-sigs/controller-runtime/issues/2622

To Reproduce

Likely other ways, but for us it was:

  1. running kubernetes 1.29
  2. deploy older vault-k8s release
  3. upgrade to 1.4
  4. kubectl logs -l app.kubernetes.io/name=vault-injector -f to see strack trace

this appears to be harmless noise, but wanted to report. health checks pass, pods are ready/running, and injection still works.

Application deployment:

including full detail here in case useful, don't judge vault version too harshly upgrade is in progress :-)

---
apiVersion: apps/v1
kind: Deployment
metadata:
  name: vault-injector
  namespace: vault
  labels:
    app.kubernetes.io/name: vault-injector
    app.kubernetes.io/instance: vault
spec:
  replicas: 2
  selector:
    matchLabels:
      app.kubernetes.io/name: vault-injector
      app.kubernetes.io/instance: vault
  template:
    metadata:
      labels:
        app.kubernetes.io/name: vault-injector
        app.kubernetes.io/instance: vault
    spec:
      affinity:
        podAntiAffinity:
          requiredDuringSchedulingIgnoredDuringExecution:
            - labelSelector:
                matchLabels:
                  app.kubernetes.io/name: vault-injector
              topologyKey: kubernetes.io/hostname
      serviceAccountName: "vault-injector"
      securityContext:
        runAsNonRoot: true
        runAsGroup: 1000
        runAsUser: 100
        fsGroup: 1000
      containers:
        - name: sidecar-injector
          image: "<repo>/vault-k8s:1.4.0"
          imagePullPolicy: IfNotPresent
          securityContext:
            allowPrivilegeEscalation: false
            capabilities:
              drop:
                - ALL
          env:
            - name: NAMESPACE
              valueFrom:
                fieldRef:
                  fieldPath: metadata.namespace
            - name: POD_NAME
              valueFrom:
                fieldRef:
                  fieldPath: metadata.name
            - name: AGENT_INJECT_LISTEN
              value: ":8080"
            - name: AGENT_INJECT_LOG_LEVEL
              value: "info"
            - name: AGENT_INJECT_LOG_FORMAT
              value: "standard"
            - name: AGENT_INJECT_VAULT_ADDR
              value: "https://vault-headless.$(NAMESPACE).svc:8200"
            - name: AGENT_INJECT_VAULT_IMAGE
              value: "<repo>/vault:1.12.2"
            - name: AGENT_INJECT_TLS_AUTO
              value: vault-agent-injector-cfg
            - name: AGENT_INJECT_TLS_AUTO_HOSTS
              value: "vault-agent-injector-svc,vault-agent-injector-svc.$(NAMESPACE),vault-agent-injector-svc.$(NAMESPACE).svc"
            - name: AGENT_INJECT_USE_LEADER_ELECTOR
              value: "true"
            - name: AGENT_INJECT_DEFAULT_TEMPLATE
              value: "map"
            - name: AGENT_INJECT_CPU_REQUEST
              value: "250m"
            - name: AGENT_INJECT_MEM_REQUEST
              value: "64Mi"
            - name: AGENT_INJECT_CPU_LIMIT
              value: "500m"
            - name: AGENT_INJECT_MEM_LIMIT
              value: "128Mi"
          args:
            - agent-inject
            - 2>&1
          livenessProbe:
            httpGet:
              path: /health/ready
              port: 8080
              scheme: HTTPS
            failureThreshold: 2
            initialDelaySeconds: 5
            periodSeconds: 2
            successThreshold: 1
            timeoutSeconds: 5
          readinessProbe:
            httpGet:
              path: /health/ready
              port: 8080
              scheme: HTTPS
            failureThreshold: 2
            initialDelaySeconds: 5
            periodSeconds: 2
            successThreshold: 1
            timeoutSeconds: 5
---
apiVersion: v1
kind: Endpoints
metadata:
  name: vault-agent-injector-leader
  namespace: vault
---
apiVersion: v1
kind: Secret
metadata:
  name: vault-injector-certs
  namespace: vault
---
apiVersion: admissionregistration.k8s.io/v1
kind: MutatingWebhookConfiguration
metadata:
  name: vault-agent-injector-cfg
  labels:
    app.kubernetes.io/name: vault-injector
    app.kubernetes.io/instance: vault
webhooks:
  - name: vault.hashicorp.com
    sideEffects: None
    admissionReviewVersions:
      - "v1"
      - "v1beta1"
    clientConfig:
      service:
        name: vault-agent-injector-svc
        path: "/mutate"
        namespace: "vault"
      caBundle: ""
    rules:
      - operations: ["CREATE", "UPDATE"]
        apiGroups: [""]
        apiVersions: ["v1"]
        resources: ["deployments", "jobs", "pods", "statefulsets"]
    namespaceSelector: {}
    objectSelector:
      matchExpressions:
      - key: app.kubernetes.io/name
        operator: NotIn
        values: ["vault-injector"]
    failurePolicy: Ignore
---
apiVersion: v1
kind: ServiceAccount
metadata:
  name: vault-injector
  namespace: vault
  labels:
    app.kubernetes.io/name: vault-injector
    app.kubernetes.io/instance: vault
---
apiVersion: rbac.authorization.k8s.io/v1
kind: ClusterRole
metadata:
  name: vault-injector-clusterrole
  labels:
    app.kubernetes.io/name: vault-injector
    app.kubernetes.io/instance: vault
rules:
  - apiGroups: ["admissionregistration.k8s.io"]
    resources: ["mutatingwebhookconfigurations"]
    verbs:
      - "get"
      - "list"
      - "watch"
      - "patch"
---
apiVersion: rbac.authorization.k8s.io/v1
kind: ClusterRoleBinding
metadata:
  name: vault-injector-binding
  labels:
    app.kubernetes.io/name: vault-injector
    app.kubernetes.io/instance: vault
roleRef:
  apiGroup: rbac.authorization.k8s.io
  kind: ClusterRole
  name: vault-injector-clusterrole
subjects:
  - kind: ServiceAccount
    name: vault-injector
    namespace: vault
---
apiVersion: rbac.authorization.k8s.io/v1
kind: Role
metadata:
  name: vault-injector-role
  namespace: vault
  labels:
    app.kubernetes.io/name: vault-injector
    app.kubernetes.io/instance: vault
rules:
  - apiGroups: [""]
    resources: ["secrets", "configmaps"]
    verbs:
      - "create"
      - "get"
      - "watch"
      - "list"
      - "update"
  - apiGroups: [""]
    resources: ["pods"]
    verbs:
      - "get"
      - "patch"
      - "delete"
---
apiVersion: rbac.authorization.k8s.io/v1
kind: RoleBinding
metadata:
  name: vault-injector-rolebinding
  namespace: vault
  labels:
    app.kubernetes.io/name: vault-injector
    app.kubernetes.io/instance: vault
roleRef:
  apiGroup: rbac.authorization.k8s.io
  kind: Role
  name: vault-injector-role
subjects:
  - kind: ServiceAccount
    name: vault-injector
    namespace: vault
---
apiVersion: v1
kind: Service
metadata:
  name: vault-agent-injector-svc
  namespace: vault
  labels:
    app.kubernetes.io/name: vault-injector
    app.kubernetes.io/instance: vault
spec:
  ports:
  - name: https
    port: 443
    targetPort: 8080
  selector:
    app.kubernetes.io/name: vault-injector
    app.kubernetes.io/instance: vault

kubectl describe deployment:

Name:                   vault-injector
Namespace:              vault
CreationTimestamp:      Thu, 04 Feb 2021 14:23:14 -0500
Labels:                 app.kubernetes.io/instance=vault
                        app.kubernetes.io/name=vault-injector
Annotations:            deployment.kubernetes.io/revision: 9
Selector:               app.kubernetes.io/instance=vault,app.kubernetes.io/name=vault-injector
Replicas:               2 desired | 2 updated | 2 total | 2 available | 0 unavailable
StrategyType:           RollingUpdate
MinReadySeconds:        0
RollingUpdateStrategy:  25% max unavailable, 25% max surge
Pod Template:
  Labels:           app.kubernetes.io/instance=vault
                    app.kubernetes.io/name=vault-injector
  Annotations:      kubectl.kubernetes.io/restartedAt: 2023-05-22T13:46:25-07:00
  Service Account:  vault-injector
  Containers:
   sidecar-injector:
    Image:      <repo>/vault-k8s:1.4.0
    Port:       <none>
    Host Port:  <none>
    Args:
      agent-inject
      2>&1
    Liveness:   http-get https://:8080/health/ready delay=5s timeout=5s period=2s #success=1 #failure=2
    Readiness:  http-get https://:8080/health/ready delay=5s timeout=5s period=2s #success=1 #failure=2
    Environment:
      NAMESPACE:                         (v1:metadata.namespace)
      POD_NAME:                          (v1:metadata.name)
      AGENT_INJECT_LISTEN:              :8080
      AGENT_INJECT_LOG_LEVEL:           info
      AGENT_INJECT_LOG_FORMAT:          standard
      AGENT_INJECT_VAULT_ADDR:          https://vault-headless.$(NAMESPACE).svc:8200
      AGENT_INJECT_VAULT_IMAGE:         <repo>/vault:1.12.2
      AGENT_INJECT_TLS_AUTO:            vault-agent-injector-cfg
      AGENT_INJECT_TLS_AUTO_HOSTS:      vault-agent-injector-svc,vault-agent-injector-svc.$(NAMESPACE),vault-agent-injector-svc.$(NAMESPACE).svc
      AGENT_INJECT_USE_LEADER_ELECTOR:  true
      AGENT_INJECT_DEFAULT_TEMPLATE:    map
      AGENT_INJECT_CPU_REQUEST:         250m
      AGENT_INJECT_MEM_REQUEST:         64Mi
      AGENT_INJECT_CPU_LIMIT:           500m
      AGENT_INJECT_MEM_LIMIT:           128Mi
    Mounts:                             <none>
  Volumes:                              <none>
Conditions:
  Type           Status  Reason
  ----           ------  ------
  Available      True    MinimumReplicasAvailable
  Progressing    True    NewReplicaSetAvailable
OldReplicaSets:  vault-injector-588767d659 (0/0 replicas created), vault-injector-79f94c59b6 (0/0 replicas created), vault-injector-565d9d955b (0/0 replicas created), vault-injector-597dbbd575 (0/0 replicas created), vault-injector-65564df78f (0/0 replicas created), vault-injector-754dd5595 (0/0 replicas created), vault-injector-68db4cf788 (0/0 replicas created), vault-injector-6db5859d4b (0/0 replicas created)
NewReplicaSet:   vault-injector-657cb7f798 (2/2 replicas created)
Events:
  Type    Reason             Age   From                   Message
  ----    ------             ----  ----                   -------
  Normal  ScalingReplicaSet  19m   deployment-controller  Scaled up replica set vault-injector-657cb7f798 to 1
  Normal  ScalingReplicaSet  14m   deployment-controller  Scaled down replica set vault-injector-6db5859d4b to 1 from 2
  Normal  ScalingReplicaSet  14m   deployment-controller  Scaled up replica set vault-injector-657cb7f798 to 2 from 1
  Normal  ScalingReplicaSet  14m   deployment-controller  Scaled down replica set vault-injector-6db5859d4b to 0 from 1

kubectl describe replicaset:

Name:           vault-injector-657cb7f798
Namespace:      vault
Selector:       app.kubernetes.io/instance=vault,app.kubernetes.io/name=vault-injector,pod-template-hash=657cb7f798
Labels:         app.kubernetes.io/instance=vault
                app.kubernetes.io/name=vault-injector
                pod-template-hash=657cb7f798
Annotations:    deployment.kubernetes.io/desired-replicas: 2
                deployment.kubernetes.io/max-replicas: 3
                deployment.kubernetes.io/revision: 9
Controlled By:  Deployment/vault-injector
Replicas:       2 current / 2 desired
Pods Status:    2 Running / 0 Waiting / 0 Succeeded / 0 Failed
Pod Template:
  Labels:           app.kubernetes.io/instance=vault
                    app.kubernetes.io/name=vault-injector
                    pod-template-hash=657cb7f798
  Annotations:      kubectl.kubernetes.io/restartedAt: 2023-05-22T13:46:25-07:00
  Service Account:  vault-injector
  Containers:
   sidecar-injector:
    Image:      <repo>/vault-k8s:1.4.0
    Port:       <none>
    Host Port:  <none>
    Args:
      agent-inject
      2>&1
    Liveness:   http-get https://:8080/health/ready delay=5s timeout=5s period=2s #success=1 #failure=2
    Readiness:  http-get https://:8080/health/ready delay=5s timeout=5s period=2s #success=1 #failure=2
    Environment:
      NAMESPACE:                         (v1:metadata.namespace)
      POD_NAME:                          (v1:metadata.name)
      AGENT_INJECT_LISTEN:              :8080
      AGENT_INJECT_LOG_LEVEL:           info
      AGENT_INJECT_LOG_FORMAT:          standard
      AGENT_INJECT_VAULT_ADDR:          https://vault-headless.$(NAMESPACE).svc:8200
      AGENT_INJECT_VAULT_IMAGE:         <repo>/vault:1.12.2
      AGENT_INJECT_TLS_AUTO:            vault-agent-injector-cfg
      AGENT_INJECT_TLS_AUTO_HOSTS:      vault-agent-injector-svc,vault-agent-injector-svc.$(NAMESPACE),vault-agent-injector-svc.$(NAMESPACE).svc
      AGENT_INJECT_USE_LEADER_ELECTOR:  true
      AGENT_INJECT_DEFAULT_TEMPLATE:    map
      AGENT_INJECT_CPU_REQUEST:         250m
      AGENT_INJECT_MEM_REQUEST:         64Mi
      AGENT_INJECT_CPU_LIMIT:           500m
      AGENT_INJECT_MEM_LIMIT:           128Mi
    Mounts:                             <none>
  Volumes:                              <none>
Events:
  Type    Reason            Age   From                   Message
  ----    ------            ----  ----                   -------
  Normal  SuccessfulCreate  25m   replicaset-controller  Created pod: vault-injector-657cb7f798-xbjgb
  Normal  SuccessfulCreate  19m   replicaset-controller  Created pod: vault-injector-657cb7f798-gmhxf
  Normal  SuccessfulCreate  19m   replicaset-controller  Created pod: vault-injector-657cb7f798-rhd6m

Expected behavior

No stack trace in logs.

Environment

tvoran commented 7 months ago

Thanks for pointing this out! I wired up an hclog -> logr type and it's trying to log this:

[ERROR] handler.leader: Failed to get Node: error="nodes \"kind-control-plane\" is forbidden: User \"system:serviceaccount:vault:vault-agent-injector\" cannot get resource \"nodes\" in API group \"\" at the cluster scope" Node.Name=kind-control-plane

That seems to be coming from the operator-lib's Become logic that we use for determining which injector replica generates TLS: https://github.com/operator-framework/operator-lib/blob/8e41bd5ce4899a67024f070e3d3286d20b2a5668/leader/leader.go#L190 So we're missing a get for nodes in the injector's ClusterRole when using multiple replicas with auto-tls.