Backups to B2 fail after the first backup

[l0wl3vel]

Description

When creating a schedule with the B2 backend instead of the S3 backend the first backup runs fine and ends sucessfully. But every subsequent backup fails with the attached logs.

Additional Context

Backups via the S3 provider run fine all the time, but we would like to use the path parameter that is only offered by the B2 provider.

Logs

Common labels: {"pod":"backup-jira-backup-vrkmz-ttlf8","stream":"stderr","app":"backup-jira-backup-vrkmz","container":"backup","job":"apps-jira/backup-jira-backup-vrkmz","namespace":"apps-jira","node_name":"hub-default-worker-78db654874-stvq4"}
Line limit: 1000
Total bytes processed: "5.29  kB"


2022-06-16T14:11:32+02:00	2022/06/16 12:11:32 unable to start k8up: failed to initialise the restic repository: cmd.Wait() err: 1
2022-06-16T14:11:32+02:00	1.6553814927560086e+09	INFO	k8up.restic.restic.RepoInit.restic.stderr	
2022-06-16T14:11:32+02:00	1.6553814927558627e+09	INFO	k8up.restic.restic.RepoInit.restic.stderr	Fatal: create repository at b2:<redacted>: failed: config already exists
2022-06-16T14:10:41+02:00	1.6553814411108267e+09	INFO	k8up.restic.restic.RepoInit.command	Defining RESTIC_PROGRESS_FPS	{"frequency": 0.016666666666666666}
2022-06-16T14:10:41+02:00	1.6553814411107955e+09	INFO	k8up.restic.restic.RepoInit.command	restic command	{"path": "/usr/local/bin/restic", "args": ["init", "--option", ""]}
2022-06-16T14:10:41+02:00	1.655381441110681e+09	INFO	k8up.restic.restic	using the following restic options	{"options": [""]}
2022-06-16T14:10:41+02:00	1.6553814411104522e+09	INFO	k8up.restic	setting up a signal handler
2022-06-16T14:10:41+02:00	1.6553814411104424e+09	INFO	k8up.restic	initializing
2022-06-16T14:10:41+02:00	1.6553814411101794e+09	INFO	k8up	Starting k8up…	{"version": "2.1.2", "date": "2022-03-30T11:52:11Z", "commit": "18c6c8c325db35068327533906b158ea29ace4ae", "go_os": "linux", "go_arch": "amd64", "go_version": "go1.17.7", "uid": 65532, "gid": 0}
2022-06-16T14:11:34+02:00	2022/06/16 12:11:34 unable to start k8up: failed to initialise the restic repository: cmd.Wait() err: 1
2022-06-16T14:11:34+02:00	1.6553814947228565e+09	INFO	k8up.restic.restic.RepoInit.restic.stderr	
2022-06-16T14:11:34+02:00	1.6553814947226834e+09	INFO	k8up.restic.restic.RepoInit.restic.stderr	Fatal: create repository at b2:<redacted>: failed: config already exists
2022-06-16T14:11:33+02:00	1.6553814938685093e+09	INFO	k8up.restic.restic.RepoInit.command	Defining RESTIC_PROGRESS_FPS	{"frequency": 0.016666666666666666}
2022-06-16T14:11:33+02:00	1.6553814938684926e+09	INFO	k8up.restic.restic.RepoInit.command	restic command	{"path": "/usr/local/bin/restic", "args": ["init", "--option", ""]}
2022-06-16T14:11:33+02:00	1.655381493868425e+09	INFO	k8up.restic.restic	using the following restic options	{"options": [""]}
2022-06-16T14:11:33+02:00	1.6553814938681972e+09	INFO	k8up.restic	setting up a signal handler
2022-06-16T14:11:33+02:00	1.6553814938681743e+09	INFO	k8up.restic	initializing
2022-06-16T14:11:33+02:00	1.6553814938679035e+09	INFO	k8up	Starting k8up…	{"version": "2.1.2", "date": "2022-03-30T11:52:11Z", "commit": "18c6c8c325db35068327533906b158ea29ace4ae", "go_os": "linux", "go_arch": "amd64", "go_version": "go1.17.7", "uid": 65532, "gid": 0}
2022-06-16T14:11:50+02:00	2022/06/16 12:11:50 unable to start k8up: failed to initialise the restic repository: cmd.Wait() err: 1
2022-06-16T14:11:50+02:00	1.6553815106177287e+09	INFO	k8up.restic.restic.RepoInit.restic.stderr	
2022-06-16T14:11:50+02:00	1.6553815106174366e+09	INFO	k8up.restic.restic.RepoInit.restic.stderr	Fatal: create repository at b2:<redacted>: failed: config already exists
2022-06-16T14:11:49+02:00	1.6553815095912876e+09	INFO	k8up.restic.restic.RepoInit.command	Defining RESTIC_PROGRESS_FPS	{"frequency": 0.016666666666666666}
2022-06-16T14:11:49+02:00	1.655381509591253e+09	INFO	k8up.restic.restic.RepoInit.command	restic command	{"path": "/usr/local/bin/restic", "args": ["init", "--option", ""]}
2022-06-16T14:11:49+02:00	1.655381509591198e+09	INFO	k8up.restic.restic	using the following restic options	{"options": [""]}
2022-06-16T14:11:49+02:00	1.655381509590994e+09	INFO	k8up.restic	setting up a signal handler
2022-06-16T14:11:49+02:00	1.655381509590959e+09	INFO	k8up.restic	initializing
2022-06-16T14:11:49+02:00	1.6553815095906625e+09	INFO	k8up	Starting k8up…	{"version": "2.1.2", "date": "2022-03-30T11:52:11Z", "commit": "18c6c8c325db35068327533906b158ea29ace4ae", "go_os": "linux", "go_arch": "amd64", "go_version": "go1.17.7", "uid": 65532, "gid": 0}
2022-06-16T14:12:15+02:00	2022/06/16 12:12:15 unable to start k8up: failed to initialise the restic repository: cmd.Wait() err: 1
2022-06-16T14:12:15+02:00	1.6553815354336944e+09	INFO	k8up.restic.restic.RepoInit.restic.stderr	
2022-06-16T14:12:15+02:00	1.655381535433541e+09	INFO	k8up.restic.restic.RepoInit.restic.stderr	Fatal: create repository at b2:<redacted>: failed: config already exists
2022-06-16T14:12:14+02:00	1.6553815345503483e+09	INFO	k8up.restic.restic.RepoInit.command	Defining RESTIC_PROGRESS_FPS	{"frequency": 0.016666666666666666}
2022-06-16T14:12:14+02:00	1.6553815345503411e+09	INFO	k8up.restic.restic.RepoInit.command	restic command	{"path": "/usr/local/bin/restic", "args": ["init", "--option", ""]}
2022-06-16T14:12:14+02:00	1.6553815345503197e+09	INFO	k8up.restic.restic	using the following restic options	{"options": [""]}
2022-06-16T14:12:14+02:00	1.6553815345501962e+09	INFO	k8up.restic	setting up a signal handler
2022-06-16T14:12:14+02:00	1.6553815345501893e+09	INFO	k8up.restic	initializing
2022-06-16T14:12:14+02:00	1.6553815345500314e+09	INFO	k8up	Starting k8up…	{"version": "2.1.2", "date": "2022-03-30T11:52:11Z", "commit": "18c6c8c325db35068327533906b158ea29ace4ae", "go_os": "linux", "go_arch": "amd64", "go_version": "go1.17.7", "uid": 65532, "gid": 0}
2022-06-16T14:12:58+02:00	2022/06/16 12:12:58 unable to start k8up: failed to initialise the restic repository: cmd.Wait() err: 1
2022-06-16T14:12:58+02:00	1.6553815784245434e+09	INFO	k8up.restic.restic.RepoInit.restic.stderr	
2022-06-16T14:12:58+02:00	1.655381578424294e+09	INFO	k8up.restic.restic.RepoInit.restic.stderr	Fatal: create repository at b2:<redacted>: failed: config already exists
2022-06-16T14:12:57+02:00	1.65538157752819e+09	INFO	k8up.restic.restic.RepoInit.command	Defining RESTIC_PROGRESS_FPS	{"frequency": 0.016666666666666666}
2022-06-16T14:12:57+02:00	1.6553815775281758e+09	INFO	k8up.restic.restic.RepoInit.command	restic command	{"path": "/usr/local/bin/restic", "args": ["init", "--option", ""]}
2022-06-16T14:12:57+02:00	1.6553815775281534e+09	INFO	k8up.restic.restic	using the following restic options	{"options": [""]}
2022-06-16T14:12:57+02:00	1.6553815775279818e+09	INFO	k8up.restic	setting up a signal handler
2022-06-16T14:12:57+02:00	1.6553815775279498e+09	INFO	k8up.restic	initializing
2022-06-16T14:12:57+02:00	1.6553815775275981e+09	INFO	k8up	Starting k8up…	{"version": "2.1.2", "date": "2022-03-30T11:52:11Z", "commit": "18c6c8c325db35068327533906b158ea29ace4ae", "go_os": "linux", "go_arch": "amd64", "go_version": "go1.17.7", "uid": 65532, "gid": 0}

Expected Behavior

Subsequent Backups run correctly and succeed.

Steps To Reproduce

1. Create a Backblaze B2 Bucket and access keys
2. Deploy the credentials needed
3. Deploy the following schedule:

apiVersion: k8up.io/v1
kind: Schedule
metadata:
  labels:
    argocd.argoproj.io/instance: jira-dependencies
  name: jira
  namespace: apps-jira
spec:
  backend:
    b2:
      accountIDSecretRef:
        key: username
        name: k8up-credentials
      accountKeySecretRef:
        key: password
        name: k8up-credentials
      bucket: <redaced>
    repoPasswordSecretRef:
      key: restic_password
      name: k8up-credentials
  backup:
    failedJobsHistoryLimit: 2
    schedule: '@hourly-random'
    successfulJobsHistoryLimit: 2
  check:
    schedule: '@weekly-random'
  prune:
    retention:
      keepDaily: 30
      keepMonthly: 6
      keepWeekly: 8
    schedule: '@weekly-random'

4. Wait for two or more backups to run

Version of K8up

v2.1.2

Version of Kubernetes

v1.23

Distribution of Kubernetes

KubeOne

[jessebot]

I'm also getting this error, but I'm using the Backup resource, instead of the Schedule resource. Same errors though, k8up calls restic to intialize the repo in the b2 bucket, and it creates the correct config, but then fails for some reason, and tries to run again, and fail loops:

1.6559117852449288e+09	INFO	k8up	Starting k8up…	{"version": "2.1.2", "date": "2022-03-30T11:52:11Z", "commit": "18c6c8c325db35068327533906b158ea29ace4ae", "go_os": "linux", "go_arch": "amd64", "go_version": "go1.17.7", "uid": 65532, "gid": 0}
1.6559117852451408e+09	INFO	k8up.restic initializing
1.6559117852452374e+09	INFO	k8up.restic setting up a signal handler
1.655911785245545e+09	INFO	k8up.restic.restic using the following restic options {"options": [""]}
1.6559117852455819e+09	INFO	k8up.restic.restic.RepoInit.command restic command {"path": "/usr/local/bin/restic", "args": ["init", "--option", ""]}
1.6559117852455904e+09	INFO	k8up.restic.restic.RepoInit.command Defining RESTIC_PROGRESS_FPS {"frequency": 0.016666666666666666}
1.6559117863848724e+09	INFO	k8up.restic.restic.RepoInit.restic.stderr Fatal: create repository at b2:myreallycoolbucket: failed: config already exists
1.6559117863850188e+09	INFO	k8up.restic.restic.RepoInit.restic.stderr 2022/06/22 15:29:46 unable to start k8up: failed to initialise the restic repository: cmd.Wait() err: 1

Interestingly this doesn't even work the first time for me to actually back anything up. It only initializes the bucket and config remotely. If I check the bucket for any actual data, there is none.

I did recently move this Backup resource to the same namespace as the stateful app I'm trying to backup. Previously my backup resource lived in the same namespace as the main k8up deployment, and it succeeded there, but couldn't find my other apps in other namespaces, so it never actually backed anything up, but successfully inited the repo and exited as completed. Since moving it to the namespace that the stateful app actually lives in, it fails consistently. Should k8up be helm installed in the same namespace as the stateful app it is monitoring?

[jessebot]

I don't think this has anything to do with the namespaces after some further testing, but I did find this:

k8up/restic/cli/init.go

Line 49 in 538ec7e

if strings.Contains(scanner.Text(), "already initialized") {

according to this function, init will error if initStdErrWrapper returns exists

// Init initialises a repository, checks if the repositor exists and will
// initialise it if not. It's save to call this every time.
func (r *Restic) Init() error {

	initLogger := r.logger.WithName("RepoInit")
	resticLogger := initLogger.WithName("restic")

	initErrorCatcher := &initStdErrWrapper{
		exists: false,
		Writer: logging.NewErrorWriter(resticLogger),
	}

	opts := CommandOptions{
		Path:   r.resticPath,
		Args:   r.globalFlags.ApplyToCommand("init"),
		StdOut: logging.NewInfoWriter(resticLogger),
		StdErr: initErrorCatcher,
	}
	cmd := NewCommand(r.ctx, initLogger, opts)
	cmd.Run()

	if !initErrorCatcher.exists {
		return cmd.FatalError
	}

	return nil
}

But if we look at that function for initStdErrWrapper:

func (i *initStdErrWrapper) Write(p []byte) (n int, err error) {
	scanner := bufio.NewScanner(bytes.NewReader(p))

	for scanner.Scan() {
		if strings.Contains(scanner.Text(), "already initialized") {
			i.exists = true
			return len(p), nil
		}
	}

It looks like it's only looking for already initialized in the stderr txt, so config already exists is not caught here, as per the logging here:

1.6559117863848724e+09	INFO	k8up.restic.restic.RepoInit.restic.stderr Fatal: create repository at b2:myreallycoolbucket: failed: config already exists

So this will always fail.

I am creating a PR to add an additional string of "config already exists" to check, because it looks like both error strings are still possible to hit as per the following:

• restic repo:backend/b2/b2.go#L126 for "config already exists"
• restic repo:repository/repository.go#L790 for "config already initialized"

Edit for more thoughts and formatting:
In additional, we could also add an repoInitialize: false param in the backend spec, to explicitly try to initialize, as it's an additional call that doesn't need to be run always anyway, and could default to true to maintain current functionality though. Something like:

spec:
  backend:
    repoInitialize: false
    repoPasswordSecretRef:
      name: k8up-restic-b2-repo-pw
      key: password

[ccremer]

Hi.
Thanks for the detailed analysis!
And even more thanks for trying to fix it on your own, as we don't have a b2 setup where we could reproduce the error and test any fixes.
We are happy to apply fixes if you manage to find the root cause.

For the time being, we would like to avoid any API changes if possible.

[jessebot]

Not a problem at all! Happy to help, as I really like this project :)

Also, that was in fact the root cause, that for backblaze specifically restic has a different text error, but in my original fix it didn't like where my for loop was for whatever reason, but then there was a second issue I started facing, which I thought was related, was actually #563

I've reopened that pull request, because the area of the code I was modifying is, in fact, correct, and I don't want this to span over too many areas in case future people want to research this. :) I don't have permission to run the GHA pipeline, but it SHOULD be ok.

EDIT: wrong issue number, updated to be correct issue number

[ccremer]

Released new bugfix: https://github.com/k8up-io/k8up/releases/tag/v2.3.3
I'm going to close this issue for the time being. If it there's still an issue, please reopen it.