search

k8up-io / k8up

Kubernetes and OpenShift Backup Operator
https://k8up.io/
Apache License 2.0
717 stars 66 forks source link

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

Closed jessebot closed 4 months ago

jessebot commented 5 months ago

Description

I always get the following in the logs of any backup pod: [controller-runtime] log.SetLogger(...) was never called; logs will not be displayed. The backup pods are always successful and the data is actually backed up, but they always print this trackback and I don't know why? Nothing is broken, just a bit confusing.

Additional Context

I'm using s3 as my backend and Backblaze B2 as the remote s3 provider. All is working there fine. Again, none of this breaks anything. It just causes weird log messages that I don't understand. Update: I switched to Cloudflare R2 and the issue persists.

Thanks for any help you can provide and thanks for continuing to maintain this project!

Logs

2024-06-22T08:34:49Z    INFO    k8up.restic.restic.backup.progress      backup finished {"new files": 0, "changed files": 56, "errors": 0}
2024-06-22T08:34:49Z    INFO    k8up.restic.restic.backup.progress      stats   {"time": 248.825449061, "bytes added": 2842538507, "bytes processed": 14227999250}
2024-06-22T08:34:49Z    INFO    k8up.restic.statsHandler.promStats      sending prometheus stats        {"url": "push-gateway.prometheus.svc:9091"}
2024-06-22T08:34:49Z    INFO    k8up.restic.restic.backup       backup finished, sending snapshot list
2024-06-22T08:34:49Z    INFO    k8up.restic.restic.snapshots    getting list of snapshots
2024-06-22T08:34:49Z    INFO    k8up.restic.restic.snapshots.command    restic command  {"path": "/usr/local/bin/restic", "args": ["snapshots", "--option", "", "--json"]}
2024-06-22T08:34:49Z    INFO    k8up.restic.restic.snapshots.command    Defining RESTIC_PROGRESS_FPS    {"frequency": 0.016666666666666666}
[controller-runtime] log.SetLogger(...) was never called; logs will not be displayed.
Detected at:
        >  goroutine 1 [running]:
        >  runtime/debug.Stack()
        >       /opt/hostedtoolcache/go/1.21.9/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.17.2/pkg/log/log.go:60 +0xcd
        >  sigs.k8s.io/controller-runtime/pkg/log.(*delegatingLogSink).WithName(0xc00003fa00, {0x1a01e56, 0x14})
        >       /home/runner/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.17.2/pkg/log/deleg.go:147 +0x45
        >  github.com/go-logr/logr.Logger.WithName({{0x1cab1c8, 0xc00003fa00}, 0x0}, {0x1a01e56?, 0x19e676a?})
        >       /home/runner/go/pkg/mod/github.com/go-logr/logr@v1.4.1/logr.go:345 +0x3d
        >  sigs.k8s.io/controller-runtime/pkg/client.newClient(0xc0003c5008?, {0x0, 0xc0004ca070, {0x0, 0x0}, 0x0, {0x0, 0x0}, 0x0})
        >       /home/runner/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.17.2/pkg/client/client.go:129 +0xec
        >  sigs.k8s.io/controller-runtime/pkg/client.New(0xc0004ca000?, {0x0, 0xc0004ca070, {0x0, 0x0}, 0x0, {0x0, 0x0}, 0x0})
        >       /home/runner/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.17.2/pkg/client/client.go:110 +0x7d
        >  github.com/k8up-io/k8up/v2/restic/kubernetes.NewTypedClient()
        >       /home/runner/work/k8up/k8up/restic/kubernetes/config.go:45 +0xb0
        >  github.com/k8up-io/k8up/v2/restic/kubernetes.SyncSnapshotList({0x1ca7638?, 0xc000184000}, {0xc000252a00, 0x1e, 0x0?}, {0xc000012019, 0x6}, {0xc000044062, 0x38})
        >       /home/runner/work/k8up/k8up/restic/kubernetes/snapshots.go:19 +0x3db
        >  github.com/k8up-io/k8up/v2/restic/cli.(*Restic).sendSnapshotList(0xc000000000)
        >       /home/runner/work/k8up/k8up/restic/cli/backup.go:116 +0x18b
        >  github.com/k8up-io/k8up/v2/restic/cli.(*Restic).Backup(0xc000000000, {0x19e7bb6, 0x5}, {0x0, 0x0, 0x0})
        >       /home/runner/work/k8up/k8up/restic/cli/backup.go:46 +0x3eb
        >  github.com/k8up-io/k8up/v2/cmd/restic.doBackup({0x1ca7328?, 0x29bde40?}, 0xc0002126c0?, {{0x1caa8a8?, 0xc0002126c0?}, 0x0?})
        >       /home/runner/work/k8up/k8up/cmd/restic/main.go:270 +0xf3
        >  github.com/k8up-io/k8up/v2/cmd/restic.run({0x1ca7328, 0x29bde40}, 0x1caa8a8?, {{0x1caa8a8?, 0xc0002126c0?}, 0x1c93950?})
        >       /home/runner/work/k8up/k8up/cmd/restic/main.go:143 +0xb6
        >  github.com/k8up-io/k8up/v2/cmd/restic.resticMain(0xc0002104c0)
        >       /home/runner/work/k8up/k8up/cmd/restic/main.go:127 +0x2c5
        >  github.com/urfave/cli/v2.(*Command).Run(0x2974ce0, 0xc0002104c0, {0xc0002125a0, 0x3, 0x3})
        >       /home/runner/go/pkg/mod/github.com/urfave/cli/v2@v2.23.7/command.go:271 +0x998
        >  github.com/urfave/cli/v2.(*Command).Run(0xc00021e640, 0xc0002106c0, {0xc00003e0c0, 0x4, 0x4})
        >       /home/runner/go/pkg/mod/github.com/urfave/cli/v2@v2.23.7/command.go:264 +0xbe5
        >  github.com/urfave/cli/v2.(*App).RunContext(0xc00021a3c0, {0x1ca7328?, 0x29bde40}, {0xc00003e0c0, 0x4, 0x4})
        >       /home/runner/go/pkg/mod/github.com/urfave/cli/v2@v2.23.7/app.go:333 +0x579
        >  github.com/urfave/cli/v2.(*App).Run(...)
        >       /home/runner/go/pkg/mod/github.com/urfave/cli/v2@v2.23.7/app.go:310
        >  main.main()
        >       /home/runner/work/k8up/k8up/cmd/k8up/main.go:30 +0x3b

Expected Behavior

No stack traces in the logs.

Steps To Reproduce

I'm using the 4.7.0 helm chart on k8s. I deploy the crds first, and then the helm chart, both via Argo CD. You can see my full values here: https://github.com/small-hack/argocd-apps/blob/730c3494444d19f8cad59184e0ba2039bcead4d6/k8up/k8up_argocd_appset.yaml#L42-L75

This happens with both Backups and Schedules manifests applied manually through kubectl.

Version of K8up

v2.10.0

Version of Kubernetes

1.29.5 originally, but I recently upgraded to v1.30.2+k3s1 and still found the error.

Distribution of Kubernetes

K3s

Kidswiss commented 4 months ago

@jessebot Does this always happen? or with specific settings? like for example pre-pod backups or backup command annotations?

From the logs it looks like the error gets thrown during the sync operation after the backup. This should ensure that for each snapshot in the restic repository there should also be a snapshot object in that namespace.

Does it write these snapshots correctly?

jessebot commented 4 months ago

Hi again!

@jessebot Does this always happen? or with specific settings? like for example pre-pod backups or backup command annotations?

Yes, this always happens to my knowledge, but I do always use backup annotations on all the PVCs I want to back up. Here's an example of the PVC:

click me for PVC.yaml ```yaml apiVersion: v1 kind: PersistentVolumeClaim metadata: annotations: k8up.io/backup: "true" pv.kubernetes.io/bind-completed: "yes" pv.kubernetes.io/bound-by-controller: "yes" volume.beta.kubernetes.io/storage-provisioner: rancher.io/local-path volume.kubernetes.io/storage-provisioner: rancher.io/local-path finalizers: - kubernetes.io/pvc-protection labels: argocd.argoproj.io/instance: nextcloud-pvc name: nextcloud-files namespace: nextcloud spec: accessModes: - ReadWriteOnce resources: requests: storage: 250Gi storageClassName: local-path volumeMode: Filesystem status: accessModes: - ReadWriteOnce capacity: storage: 250Gi phase: Bound ```

Here's an example of a backup that I ran recently:

click me for Backup.yaml ```yaml apiVersion: k8up.io/v1 kind: Backup metadata: name: nextcloud-smol-k8s-lab-2024-07-22-14-12 namespace: nextcloud spec: failedJobsHistoryLimit: 5 promURL: push-gateway.prometheus.svc:9091 successfulJobsHistoryLimit: 1 backend: repoPasswordSecretRef: key: resticRepoPassword name: s3-backups-credentials s3: accessKeyIDSecretRef: key: accessKeyId name: s3-backups-credentials optional: false bucket: my-nextcloud-backups endpoint: https://12345.eu.r2.cloudflarestorage.com secretAccessKeySecretRef: key: secretAccessKey name: s3-backups-credentials optional: false podConfigRef: name: backups-podconfig podSecurityContext: runAsUser: 82 ```

Here's the full backup pod log from top to bottom, from the above Backup resource (I don't think there's any sensitive info here):

click me for pod.log ```logtalk 2024-07-22T12:15:48Z INFO k8up Starting k8up… {"version": "2.10.0", "date": "2024-05-15T07:41:14Z", "commit": "212a03389a3298ee003faa94acf04c8a0fccaa78", "go_os": "linux", "go_arch": "amd64", "go_version": "go1.21.9", "uid": 82, "gid": 0} 2024-07-22T12:15:48Z INFO k8up.restic initializing 2024-07-22T12:15:48Z INFO k8up.restic setting up a signal handler 2024-07-22T12:15:48Z INFO k8up.restic.restic using the following restic options {"options": [""]} 2024-07-22T12:15:48Z INFO k8up.restic.restic.RepoInit.command restic command {"path": "/usr/local/bin/restic", "args": ["init", "--option", ""]} 2024-07-22T12:15:48Z INFO k8up.restic.restic.RepoInit.command Defining RESTIC_PROGRESS_FPS {"frequency": 0.016666666666666666} 2024-07-22T12:15:49Z INFO k8up.restic.restic.unlock unlocking repository {"all": false} 2024-07-22T12:15:49Z INFO k8up.restic.restic.unlock.command restic command {"path": "/usr/local/bin/restic", "args": ["unlock", "--option", ""]} 2024-07-22T12:15:49Z INFO k8up.restic.restic.unlock.command Defining RESTIC_PROGRESS_FPS {"frequency": 0.016666666666666666} 2024-07-22T12:15:51Z INFO k8up.restic.restic.snapshots getting list of snapshots 2024-07-22T12:15:51Z INFO k8up.restic.restic.snapshots.command restic command {"path": "/usr/local/bin/restic", "args": ["snapshots", "--option", "", "--json"]} 2024-07-22T12:15:51Z INFO k8up.restic.restic.snapshots.command Defining RESTIC_PROGRESS_FPS {"frequency": 0.016666666666666666} 2024-07-22T12:15:56Z INFO k8up.restic.k8sClient listing all pods {"annotation": "k8up.io/backupcommand", "namespace": "nextcloud"} 2024-07-22T12:15:56Z INFO k8up.restic backups of annotated jobs have finished successfully 2024-07-22T12:15:56Z INFO k8up.restic.restic.backup starting backup 2024-07-22T12:15:56Z INFO k8up.restic.restic.backup starting backup for folder {"foldername": "nextcloud-files"} 2024-07-22T12:15:56Z INFO k8up.restic.restic.backup.command restic command {"path": "/usr/local/bin/restic", "args": ["backup", "--option", "", "--host", "nextcloud", "--json", "/data/nextcloud-files"]} 2024-07-22T12:15:56Z INFO k8up.restic.restic.backup.command Defining RESTIC_PROGRESS_FPS {"frequency": 0.016666666666666666} 2024-07-22T12:16:58Z INFO k8up.restic.restic.backup.progress progress of backup {"percentage": "22.90%"} 2024-07-22T12:17:58Z INFO k8up.restic.restic.backup.progress progress of backup {"percentage": "24.11%"} 2024-07-22T12:18:58Z INFO k8up.restic.restic.backup.progress progress of backup {"percentage": "25.26%"} 2024-07-22T12:19:58Z INFO k8up.restic.restic.backup.progress progress of backup {"percentage": "26.38%"} 2024-07-22T12:20:58Z INFO k8up.restic.restic.backup.progress progress of backup {"percentage": "38.76%"} 2024-07-22T12:21:58Z INFO k8up.restic.restic.backup.progress progress of backup {"percentage": "88.47%"} 2024-07-22T12:22:58Z INFO k8up.restic.restic.backup.progress progress of backup {"percentage": "89.76%"} 2024-07-22T12:23:58Z INFO k8up.restic.restic.backup.progress progress of backup {"percentage": "90.91%"} 2024-07-22T12:24:58Z INFO k8up.restic.restic.backup.progress progress of backup {"percentage": "91.97%"} 2024-07-22T12:25:58Z INFO k8up.restic.restic.backup.progress progress of backup {"percentage": "93.09%"} 2024-07-22T12:26:58Z INFO k8up.restic.restic.backup.progress progress of backup {"percentage": "94.19%"} 2024-07-22T12:27:58Z INFO k8up.restic.restic.backup.progress progress of backup {"percentage": "95.43%"} 2024-07-22T12:28:33Z INFO k8up.restic.restic.backup.progress backup finished {"new files": 59778, "changed files": 0, "errors": 0} 2024-07-22T12:28:33Z INFO k8up.restic.restic.backup.progress stats {"time": 754.634161976, "bytes added": 9210820522, "bytes processed": 68455712999} 2024-07-22T12:28:33Z INFO k8up.restic.statsHandler.promStats sending prometheus stats {"url": "push-gateway.prometheus.svc:9091"} 2024-07-22T12:28:34Z INFO k8up.restic.restic.backup starting backup for folder {"foldername": "swfs-filer-data"} 2024-07-22T12:28:34Z INFO k8up.restic.restic.backup.command restic command {"path": "/usr/local/bin/restic", "args": ["backup", "--option", "", "--host", "nextcloud", "--json", "/data/swfs-filer-data"]} 2024-07-22T12:28:34Z INFO k8up.restic.restic.backup.command Defining RESTIC_PROGRESS_FPS {"frequency": 0.016666666666666666} 2024-07-22T12:28:39Z INFO k8up.restic.restic.backup.progress backup finished {"new files": 0, "changed files": 7, "errors": 0} 2024-07-22T12:28:39Z INFO k8up.restic.restic.backup.progress stats {"time": 3.729994915, "bytes added": 1041429, "bytes processed": 4549497} 2024-07-22T12:28:39Z INFO k8up.restic.statsHandler.promStats sending prometheus stats {"url": "push-gateway.prometheus.svc:9091"} 2024-07-22T12:28:39Z INFO k8up.restic.restic.backup starting backup for folder {"foldername": "swfs-volume-data"} 2024-07-22T12:28:39Z INFO k8up.restic.restic.backup.command restic command {"path": "/usr/local/bin/restic", "args": ["backup", "--option", "", "--json", "--host", "nextcloud", "/data/swfs-volume-data"]} 2024-07-22T12:28:39Z INFO k8up.restic.restic.backup.command Defining RESTIC_PROGRESS_FPS {"frequency": 0.016666666666666666} 2024-07-22T12:29:41Z INFO k8up.restic.restic.backup.progress progress of backup {"percentage": "82.87%"} 2024-07-22T12:30:35Z INFO k8up.restic.restic.backup.progress backup finished {"new files": 0, "changed files": 42, "errors": 0} 2024-07-22T12:30:35Z INFO k8up.restic.restic.backup.progress stats {"time": 114.258577374, "bytes added": 1379844004, "bytes processed": 25459909402} 2024-07-22T12:30:35Z INFO k8up.restic.statsHandler.promStats sending prometheus stats {"url": "push-gateway.prometheus.svc:9091"} 2024-07-22T12:30:36Z INFO k8up.restic.restic.backup backup finished, sending snapshot list 2024-07-22T12:30:36Z INFO k8up.restic.restic.snapshots getting list of snapshots 2024-07-22T12:30:36Z INFO k8up.restic.restic.snapshots.command restic command {"path": "/usr/local/bin/restic", "args": ["snapshots", "--option", "", "--json"]} 2024-07-22T12:30:36Z INFO k8up.restic.restic.snapshots.command Defining RESTIC_PROGRESS_FPS {"frequency": 0.016666666666666666} [controller-runtime] log.SetLogger(...) was never called; logs will not be displayed. Detected at: > goroutine 1 [running]: > runtime/debug.Stack() > /opt/hostedtoolcache/go/1.21.9/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.17.2/pkg/log/log.go:60 +0xcd > sigs.k8s.io/controller-runtime/pkg/log.(*delegatingLogSink).WithName(0xc00003fa00, {0x1a01e56, 0x14}) > /home/runner/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.17.2/pkg/log/deleg.go:147 +0x45 > github.com/go-logr/logr.Logger.WithName({{0x1cab1c8, 0xc00003fa00}, 0x0}, {0x1a01e56?, 0x19e676a?}) > /home/runner/go/pkg/mod/github.com/go-logr/logr@v1.4.1/logr.go:345 +0x3d > sigs.k8s.io/controller-runtime/pkg/client.newClient(0xc000303008?, {0x0, 0xc00022e700, {0x0, 0x0}, 0x0, {0x0, 0x0}, 0x0}) > /home/runner/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.17.2/pkg/client/client.go:129 +0xec > sigs.k8s.io/controller-runtime/pkg/client.New(0xc00022e690?, {0x0, 0xc00022e700, {0x0, 0x0}, 0x0, {0x0, 0x0}, 0x0}) > /home/runner/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.17.2/pkg/client/client.go:110 +0x7d > github.com/k8up-io/k8up/v2/restic/kubernetes.NewTypedClient() > /home/runner/work/k8up/k8up/restic/kubernetes/config.go:45 +0xb0 > github.com/k8up-io/k8up/v2/restic/kubernetes.SyncSnapshotList({0x1ca7638?, 0xc0004c0000}, {0xc0002daa00, 0x21, 0x0?}, {0xc000044009, 0x9}, {0xc00004e012, 0x63}) > /home/runner/work/k8up/k8up/restic/kubernetes/snapshots.go:19 +0x3db > github.com/k8up-io/k8up/v2/restic/cli.(*Restic).sendSnapshotList(0xc0004c80c0) > /home/runner/work/k8up/k8up/restic/cli/backup.go:116 +0x18b > github.com/k8up-io/k8up/v2/restic/cli.(*Restic).Backup(0xc0004c80c0, {0x19e7bb6, 0x5}, {0x0, 0x0, 0x0}) > /home/runner/work/k8up/k8up/restic/cli/backup.go:46 +0x3eb > github.com/k8up-io/k8up/v2/cmd/restic.doBackup({0x1ca7328?, 0x29bde40?}, 0xc0004c65d0?, {{0x1caa8a8?, 0xc0004c65d0?}, 0x0?}) > /home/runner/work/k8up/k8up/cmd/restic/main.go:270 +0xf3 > github.com/k8up-io/k8up/v2/cmd/restic.run({0x1ca7328, 0x29bde40}, 0x1caa8a8?, {{0x1caa8a8?, 0xc0004c65d0?}, 0x1c93950?}) > /home/runner/work/k8up/k8up/cmd/restic/main.go:143 +0xb6 > github.com/k8up-io/k8up/v2/cmd/restic.resticMain(0xc00003fb00) > /home/runner/work/k8up/k8up/cmd/restic/main.go:127 +0x2c5 > github.com/urfave/cli/v2.(*Command).Run(0x2974ce0, 0xc00003fb00, {0xc00043db60, 0x3, 0x3}) > /home/runner/go/pkg/mod/github.com/urfave/cli/v2@v2.23.7/command.go:271 +0x998 > github.com/urfave/cli/v2.(*Command).Run(0xc000242500, 0xc00003f0c0, {0xc00003e0c0, 0x4, 0x4}) > /home/runner/go/pkg/mod/github.com/urfave/cli/v2@v2.23.7/command.go:264 +0xbe5 > github.com/urfave/cli/v2.(*App).RunContext(0xc0004cc000, {0x1ca7328?, 0x29bde40}, {0xc00003e0c0, 0x4, 0x4}) > /home/runner/go/pkg/mod/github.com/urfave/cli/v2@v2.23.7/app.go:333 +0x579 > github.com/urfave/cli/v2.(*App).Run(...) > /home/runner/go/pkg/mod/github.com/urfave/cli/v2@v2.23.7/app.go:310 > main.main() > /home/runner/work/k8up/k8up/cmd/k8up/main.go:30 +0x3b ```

Here's my k8up helm chart values (indentation is weird because it's passed into an Argo CD Application valuesObject), perhaps most notable is k8up.skipWithoutAnnotation=True:

click me for helm_values.yaml ```yaml k8up: # -- Specifies the timezone K8up is using for scheduling. # Empty value defaults to the timezone in which Kubernetes is deployed. # Accepts `tz database` compatible entries, e.g. `Europe/Zurich` timezone: '{{ .global_time_zone }}' skipWithoutAnnotation: true metrics: service: port: 8080 type: ClusterIP # -- Service node port of the metrics endpoint, requires `metrics.service.type=NodePort` nodePort: 0 serviceMonitor: # -- Whether to enable ServiceMonitor manifests for # [Prometheus Operator][prometheus-operator] enabled: true # -- Scrape interval to collect metrics scrapeInterval: 15s # -- If the object should be installed in a different namespace than operator namespace: "" # -- Add labels to the ServiceMonitor object additionalLabels: {} resources: limits: # -- Memory limit of K8up operator. See [supported units][resource-units]. memory: 256Mi requests: # -- CPU request of K8up operator. See [supported units][resource-units]. cpu: 20m # -- Memory request of K8up operator. See [supported units][resource-units]. memory: 128Mi ```

From the logs it looks like the error gets thrown during the sync operation after the backup. This should ensure that for each snapshot in the restic repository there should also be a snapshot object in that namespace.

Does it write these snapshots correctly?

Yes, they are written correctly actually! That's what's really weird. This also happens if there's errors in the logs, but as shown above, it happens when everything is successful as well. I checked the snapshots and they all look ok. I just started a restore of one of them to local disk and although it's 63G and my internet isn't great, it is actually restoring properly. It's at about 25% restored right now and all seems well. Update: it restored fine! :)

Let me know if there's any other info I can provide! 🙏

Kidswiss commented 4 months ago

Thanks for the details I'll try to reproduce it.

What I find really strange, according to the stacktrace it happens within the creation of the k8s client we use to write the snapshot objects to the cluster.

jessebot commented 4 months ago

@Kidswiss thanks for the fix! Could I please ask when this will be released in the helm chart? Kind regards! :)

Kidswiss commented 4 months ago

@Kidswiss thanks for the fix! Could I please ask when this will be released in the helm chart? Kind regards! :)

The release pipeline is running as I'm writing this :)