Backup is Triggered with same backupNumber

[pniederlag]

Due to the size of the backup we only trigger a backup every two hours (interval: 7200).

For some - yet unknown - reasons in some cases the backup is being triggered twice in a very short time. Our backup script by now detects that problem and will exit (without error).

Find an excerpt from the logs below.

backups 1284 and 1287 did work according to expectations. backups 1285, 1286, 1288 und 1289 have been run twice

We have already slightly adapted the backup and restore scripts in order to trace the issues. A crucial part might be the proper way of emitting and handling signals in the script.

grep -i backup /tmp/jenkins-operator.log | grep -E 'Performing|Skipping backup'
2024-01-25T23:06:03.961Z    INFO    controller-jenkins  Performing backup '1284'    {"cr": "prod"}
2024-01-25T23:06:55.151Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-25T23:35:22.977Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-25T23:35:23.758Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T00:38:18.545Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T00:38:19.286Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T01:06:03.918Z    INFO    controller-jenkins  Performing backup '1285'    {"cr": "prod"}
2024-01-26T01:06:55.557Z    INFO    controller-jenkins  Performing backup '1285'    {"cr": "prod"}
2024-01-26T01:06:56.787Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T01:06:57.705Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T01:35:37.510Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T01:35:38.172Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T02:32:46.358Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T02:32:47.077Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T02:33:58.747Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T02:33:59.429Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T03:06:03.917Z    INFO    controller-jenkins  Performing backup '1286'    {"cr": "prod"}
2024-01-26T03:06:55.142Z    INFO    controller-jenkins  Performing backup '1286'    {"cr": "prod"}
2024-01-26T03:06:56.532Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T03:06:57.253Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T03:32:40.676Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T03:32:41.379Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T04:29:58.425Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T04:29:59.113Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T05:06:05.006Z    INFO    controller-jenkins  Performing backup '1287'    {"cr": "prod"}
2024-01-26T05:06:56.149Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T05:06:56.870Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T05:30:03.700Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T05:30:04.440Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T05:31:51.007Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T05:31:52.746Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T06:22:14.584Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T06:22:16.399Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T06:28:27.716Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T06:28:28.687Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T07:06:03.963Z    INFO    controller-jenkins  Performing backup '1288'    {"cr": "prod"}
2024-01-26T07:06:55.935Z    INFO    controller-jenkins  Performing backup '1288'    {"cr": "prod"}
2024-01-26T07:06:57.606Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T07:06:58.476Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T07:23:46.648Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T07:25:58.041Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T07:25:58.733Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T08:23:19.967Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T08:23:20.914Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T09:03:23.164Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T09:03:23.898Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T09:06:04.003Z    INFO    controller-jenkins  Performing backup '1289'    {"cr": "prod"}
2024-01-26T09:06:55.305Z    INFO    controller-jenkins  Performing backup '1289'    {"cr": "prod"}
2024-01-26T09:06:56.471Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T09:06:57.307Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T09:25:09.829Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T09:25:10.578Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T09:39:58.047Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}
2024-01-26T09:39:58.783Z    DEBUG   controller-jenkins  Skipping backup {"cr": "prod"}

used backup script

  backup.sh: |
    #!/usr/bin/env bash

    set -eo pipefail
    #set -xv

    [[ ! $# -eq 1 ]] && echo "Usage: $0 backup_number" && exit 1;
    [[ -z "${BACKUP_DIR}" ]] && echo "Required 'BACKUP_DIR' env not set" && exit 1;
    [[ -z "${JENKINS_HOME}" ]] && echo "Required 'JENKINS_HOME' env not set" && exit 1;

    backup_number=$1
    echo "Running backup"

    LOCK_FILE="${BACKUP_DIR}/.backup-running"
    # debug logging to check for weird errors START
    echo "----------------------------------------" >> ${BACKUP_DIR}/debug.log
    echo "$(date +'%F %H:%M:%S %Z') Custom backup ${backup_number} START" >> ${BACKUP_DIR}/debug.log

    # 1. check: test LOCK_FILE to prevent concurrent backups
    if [[ -f "${LOCK_FILE}" ]]; then
      echo "$(date +'%F %H:%M:%S %Z') lock ${LOCK_FILE} exists, SHOULD NOT HAPPEN" >> ${BACKUP_DIR}/debug.log
      # ignore if older than one day
      if [ "$(find ${LOCK_FILE} -mtime +1)" ]; then
        echo "$(date +'%F %H:%M:%S %Z') ignoring ${LOCK_FILE} as its more than one day old" >> ${BACKUP_DIR}/debug.log
      else
        echo "$(date +'%F %H:%M:%S %Z') skipping backup because it is locked by ${LOCK_FILE}, SHOULD NOT HAPPEN" >> ${BACKUP_DIR}/debug.log
        exit 0
      fi
    fi

    BACKUP_TMP_DIR=$(mktemp -d)
    # as we now work via tmp-dir it is very unlikely the backup already exists in final destination
    # yet we keep this check in here as an additional safety check
    # 2. check: this backup number already finished?
    if [[ -e ${BACKUP_DIR}/${backup_number}.tar.gz ]]; then
      echo "${backup_number} already existing, SHOULD NOT HAPPEN" >> ${BACKUP_DIR}/debug.log
      echo "$(date +'%F %H:%M:%S %Z') Custom backup ${backup_number} FAIL/EXISTS" >> ${BACKUP_DIR}/debug.log
      exit 0
    fi
    # debug logging to check for weird errors END

    # Start backup by setting the lock-file, prevent concurrent executions
    touch ${LOCK_FILE}
    # the user of the jenkins-operator will create a fresh/new directory on each installation
    # that's the reason we keep the directory of this special user out of the backup
    # we must catch exit code 1, as tar will exit with status 1 when files have been changed during backup
    tar -C ${JENKINS_HOME} --ignore-failed-read --no-wildcards-match-slash --anchored --exclude=jobs/seed-job-post-init --exclude=jobs/*/workspace* --exclude=jobs/*/config.xml --exclude=jobs/*/state.xml --exclude=users/jenkinsoperato_* --exclude=users/jenkinsdev_* --exclude=jobs/**/builds/[0-9]*/libs -czf "${BACKUP_TMP_DIR}/${backup_number}.tar.gz" jobs users userContent ||  [[ $? -eq 1 ]]
    cp ${BACKUP_TMP_DIR}/${backup_number}.tar.gz ${BACKUP_DIR}/${backup_number}.tar.gz

    # Cleanup of tmp dir and lock-file
    rm -rf ${BACKUP_TMP_DIR}
    rm -f ${LOCK_FILE}

    if [[ ! -s ${BACKUP_DIR}/${backup_number}.tar.gz ]]; then
      echo "backup file '${BACKUP_DIR}/${backup_number}.tar.gz' is empty"
      echo "$(date +'%F %H:%M:%S %Z') Custom backup ${backup_number} FAIL/EMPTY" >> ${BACKUP_DIR}/debug.log
      exit 1
    fi

    echo "$(date +'%F %H:%M:%S %Z') Custom backup ${backup_number} DONE" >> ${BACKUP_DIR}/debug.log

    echo "Done"
    exit 0

[pniederlag]

Same thing is true for restoring the backup... btw... we see two consecutive runs

2024-02-01T13:37:48.329Z    INFO    controller-jenkins  Restoring backup '1386' {"cr": "test"}
2024-02-01T13:38:43.901Z    INFO    controller-jenkins  Restoring backup '1386' {"cr": "test"}

Why is this message triggered twice? and why does reconcilliation continue without waiting for the restore to finish?

We have confirmed on the pod/container that there are two instances of restore.sh running... which seems not the way it should work

[brokenpip3]

We have confirmed on the pod/container that there are two instances of restore.sh running... which seems not the way it should work

this is odd, can you send me the ps -ef inside the backup container? I never saw this issue with few seconds between 2 backups. Can you also send the jenkins crd? remove the sensitive parts, only the backup config

[pniederlag]

Thx for taking a look into it... Here is the output of 'ps -ef'.

root@jenkins-test:/home/user/bin# ps -ef
UID          PID    PPID  C STIME TTY          TIME CMD
root           1       0  0 10:39 ?        00:00:00 /bin/sh -c ./run.sh
root           7       1  0 10:39 ?        00:00:00 bash ./run.sh
root           9       7  0 10:39 ?        00:00:00 sleep 7200
root         148       0  0 10:42 ?        00:00:00 bash /home/user/bin/restore.sh 1433
root         162     148  0 10:42 ?        00:00:00 sleep 900
root         302       0  0 10:43 ?        00:00:00 bash /home/user/bin/restore.sh 1433
root         316     302  0 10:43 ?        00:00:00 sleep 900
root         332       0  0 10:49 pts/0    00:00:00 sh -c clear; (bash || ash || sh)
root         339     332  0 10:49 pts/0    00:00:00 sh -c clear; (bash || ash || sh)
root         340     339  0 10:49 pts/0    00:00:00 bash
root         341     340  0 10:49 pts/0    00:00:00 ps -ef

and the crd

jenkins-test-yaml.txt

scripts are adapted and mounted from our configmap.

It might be worth mentioning that we have PROD and TEST running in the very same cluster on different namespaces... (operator is duplicated as well and each one only watching its own namespace)

[brokenpip3]

This is clearly a new instance of the operator that is trying to restore the same backup, we may need to add a more safe mechanism that will avoid the operator to run again the restore command and the backup to avoid to start if another is running. Will do somewhere in the near future

[DionJones615]

We've also seen duplicated restores, but in this case it's every time on every instance and they appear to be consecutive, not concurrent.

This PR fixed it for us. Unsure if this is related, but worth a look. #1021

After giving it a second look, I think the backup issue occurs if jenkins-operator restarts. Similar to the restore issue I discovered, the .Update() function can fail if the client is not defined yet. Similar to my fix for Restore, I added the same .Get() for Backup.

[brokenpip3]

Thanks a lot for the restore fix! However for the double backup/restore it's more complicated than this. The problem is that with the current logic one of the first action will be to run the backup script in jenkins with a simple kube exec into the pod. With this logic if the operator will crash/respawn at the same time after the restart it will be not able to understand if there is a backup process that is still in running in the jenkins pod. This could be fixed at 2 level:

• Operator logic, we can note the backup pid in the crd status and check for it each time before updating the backup status/running a new backup
• Backup script logic: we can use a semaphore of any type (file for instance) to avoid run another backup and instead wait until the old one will end or goes to error etc (it will be important to add this part to the bash script trap). Finally after waiting x times for y seconds it will goes in error (to avoid waiting forever)

Honestly based on the operator code I'm more incline to add this logic to the backup script, since the original authors of this operator make the operator to be agnostic of the type and logic of the backup. It should be not so complex, I can try in the following days

[brokenpip3]

I started the work on this PR

you can test it with this temporary image: quay.io/jenkins-kubernetes-operator/backup-pvc:7a4cbf98

[brokenpip3]

Ok I think that now is stable to test: quay.io/jenkins-kubernetes-operator/backup-pvc:5f5c8e17 any feedback will be appreciated, I will add some docs before merging the PR.

[brokenpip3]

The new 0.8.1 should fix this issue, let me know if it's not like that, drop a comment and I will re-open the issue.