Uploaded image for project: 'Jenkins'
  1. Jenkins
  2. JENKINS-49909

Cannot initialize BackupSet from ZIP file + orphaned diff backups

    Details

    • Type: Bug
    • Status: Open (View Workflow)
    • Priority: Major
    • Resolution: Unresolved
    • Component/s: thinbackup-plugin
    • Labels:
      None
    • Environment:
      Jenkins version: 2.109
      thinBackup version: 1.9
      Backup location: NFS share
    • Similar Issues:

      Description

      Hello!

      I've been using thinBackup for two weeks. They are set to full backup once a week and daily differential backups. In theory, everything works fine, except backup rotation. There you have my scheduler:

      FULL: H(0-15) 1 * * 1

      DIFF: H(0-15) 1 * * 2-7

      Last full backup was made today, 5th of March, at 1 A.M. Previous FULL was made one week ago, 26th of February at 1 A.M. First full backup wad made manually, 23rd of February.

      At every backup rotation I see the following logs:

       

      Mar 05, 2018 1:42:26 AM SEVERE org.jvnet.hudson.plugins.thinbackup.backup.BackupSet initializeFromZipFile
      Cannot initialize BackupSet from ZIP file 'BACKUPSET_2018-02-26_01-00_2018-03-04_01-00.zip'.
      java.util.zip.ZipException: zip file is empty
      	at java.util.zip.ZipFile.open(Native Method)
      	at java.util.zip.ZipFile.<init>(ZipFile.java:225)
      	at java.util.zip.ZipFile.<init>(ZipFile.java:155)
      	at java.util.zip.ZipFile.<init>(ZipFile.java:169)
      	at org.jvnet.hudson.plugins.thinbackup.backup.BackupSet.initializeFromZipFile(BackupSet.java:124)
      	at org.jvnet.hudson.plugins.thinbackup.backup.BackupSet.initialize(BackupSet.java:93)
      	at org.jvnet.hudson.plugins.thinbackup.backup.BackupSet.<init>(BackupSet.java:79)
      	at org.jvnet.hudson.plugins.thinbackup.utils.Utils.getValidBackupSetsFromZips(Utils.java:353)
      	at org.jvnet.hudson.plugins.thinbackup.utils.Utils.getValidBackupSets(Utils.java:372)
      	at org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup.removeSuperfluousBackupSets(HudsonBackup.java:498)
      	at org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup.backup(HudsonBackup.java:178)
      	at org.jvnet.hudson.plugins.thinbackup.ThinBackupPeriodicWork.backupNow(ThinBackupPeriodicWork.java:89)
      	at org.jvnet.hudson.plugins.thinbackup.ThinBackupPeriodicWork.execute(ThinBackupPeriodicWork.java:70)
      	at org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork$1.run(AsyncPeriodicWork.java:53)
      	at java.lang.Thread.run(Thread.java:748)
      
      Mar 05, 2018 1:42:26 AM WARNING org.jvnet.hudson.plugins.thinbackup.backup.BackupSet 
      Could not initialize backup set from file/directory 'BACKUPSET_2018-02-26_01-00_2018-03-04_01-00.zip' as it is not valid.
      Mar 05, 2018 2:47:38 AM INFO org.jvnet.hudson.plugins.thinbackup.utils.Utils moveOldBackupsToZipFile
      DONE moving 1 backup set(s) to ZIP files.
      

      ALSO one od differential backups is always orphaned - first from chain. Let assume we have the following chains:

       

      23.02(FULL) -> 24.02(DIFF) -> 25.02(DIFF)
      
      26.02(FULL) -> 27.02(DIFF) -> 28.02(DIFF) -> 01.03(DIFF) -> 02.03(DIFF) -> 03.03(DIFF) -> 04.03(DIFF) ->

      24.02 and 27.02 won't be included to the ZIP file. Please take a look at the directories from the last ZIP file:

       

      $ zipinfo -1 BACKUPSET_2018-02-26_01-00_2018-03-04_01-00.zip | awk -F'/' '{ print $1 }' | uniq
      FULL-2018-02-26_01-00
      DIFF-2018-02-28_01-00
      DIFF-2018-03-01_01-00
      DIFF-2018-03-02_01-00
      DIFF-2018-03-03_01-00
      DIFF-2018-03-04_01-00

      There is no DIFF-2018-02-27_01-00. But I can find that dir in the main backup directory:

      ls -al /backups/jenkinsBackups
      total 60380
      jenkins jenkins 203 Mar 5 02:47 .
      root root 28 Feb 23 12:35 ..
      jenkins jenkins 28027061 Feb 26 02:09 BACKUPSET_2018-02-23_12-43_2018-02-25_01-00.zip
      jenkins jenkins 33783919 Mar 5 02:23 BACKUPSET_2018-02-26_01-00_2018-03-04_01-00.zip
      jenkins jenkins 132 Feb 24 01:17 DIFF-2018-02-24_01-00
      jenkins jenkins 4096 Feb 27 01:16 DIFF-2018-02-27_01-00
      jenkins jenkins 4096 Mar 5 01:42 FULL-2018-03-05_01-00

      First backupset has the same situation:

      $ zipinfo -1 BACKUPSET_2018-02-23_12-43_2018-02-25_01-00.zip | awk -F'/' '{ print $1 }' | uniq
      FULL-2018-02-23_12-43
      DIFF-2018-02-25_01-00

      Today, 5th of March was created a new full backup. So I should have only two more files here - backupsets. But as you can see, there are two additional directories:

      • DIFF-2018-02-24_01-00
      • DIFF-2018-02-27_01-00

      They are the first differential backups from the existing chains. 

      It's very weird behaviour. In theory ZIP files are operational, but I didn't try to restore Jenkins configuration from that Backupsets, so I am not sure whether are they working properly or not. Could you please invetigate this issue?

      If you need some more information, please let me know. There you have the full stacktrace from the last thinBackup job:

      Mar 05, 2018 1:00:35 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 7 jobs to back up.
      Mar 05, 2018 1:01:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:01:48 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 5 jobs to back up.
      Mar 05, 2018 1:02:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:03:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:04:10 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 1 jobs to back up.
      Mar 05, 2018 1:04:11 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 5 jobs to back up.
      Mar 05, 2018 1:04:19 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 2 jobs to back up.
      Mar 05, 2018 1:04:19 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 9 jobs to back up.
      Mar 05, 2018 1:04:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:05:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:06:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:07:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:08:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:09:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:10:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:11:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:12:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:12:35 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 17 jobs to back up.
      Mar 05, 2018 1:12:35 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 2 jobs to back up.
      Mar 05, 2018 1:12:45 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 17 jobs to back up.
      Mar 05, 2018 1:13:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:13:53 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 13 jobs to back up.
      Mar 05, 2018 1:14:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:15:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:16:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:16:38 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 4 jobs to back up.
      Mar 05, 2018 1:17:02 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 13 jobs to back up.
      Mar 05, 2018 1:17:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:18:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:19:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:20:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:21:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:22:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:23:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:24:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:25:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:26:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:27:10 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 4 jobs to back up.
      Mar 05, 2018 1:27:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:28:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:29:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:29:36 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 2 jobs to back up.
      Mar 05, 2018 1:29:46 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 2 jobs to back up.
      Mar 05, 2018 1:30:12 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 3 jobs to back up.
      Mar 05, 2018 1:30:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:30:26 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 3 jobs to back up.
      Mar 05, 2018 1:30:47 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 2 jobs to back up.
      Mar 05, 2018 1:30:56 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 3 jobs to back up.
      Mar 05, 2018 1:31:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:31:25 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 2 jobs to back up.
      Mar 05, 2018 1:31:33 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 3 jobs to back up.
      Mar 05, 2018 1:31:54 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 3 jobs to back up.
      Mar 05, 2018 1:32:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:32:30 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 2 jobs to back up.
      Mar 05, 2018 1:32:38 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 3 jobs to back up.
      Mar 05, 2018 1:33:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:34:20 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 1 jobs to back up.
      Mar 05, 2018 1:34:20 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 3 jobs to back up.
      Mar 05, 2018 1:34:21 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 17 jobs to back up.
      Mar 05, 2018 1:34:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:34:42 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 3 jobs to back up.
      Mar 05, 2018 1:34:59 AM INFO org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup backupJobsDirectory
      Found 3 jobs to back up.
      Mar 05, 2018 1:35:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:36:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:37:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:38:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:39:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:40:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:41:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:42:21 AM WARNING org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork doRun
      ThinBackup Worker Thread thread is still running. Execution aborted.
      Mar 05, 2018 1:42:26 AM SEVERE org.jvnet.hudson.plugins.thinbackup.backup.BackupSet initializeFromZipFile
      Cannot initialize BackupSet from ZIP file 'BACKUPSET_2018-02-26_01-00_2018-03-04_01-00.zip'.
      java.util.zip.ZipException: zip file is empty
      	at java.util.zip.ZipFile.open(Native Method)
      	at java.util.zip.ZipFile.<init>(ZipFile.java:225)
      	at java.util.zip.ZipFile.<init>(ZipFile.java:155)
      	at java.util.zip.ZipFile.<init>(ZipFile.java:169)
      	at org.jvnet.hudson.plugins.thinbackup.backup.BackupSet.initializeFromZipFile(BackupSet.java:124)
      	at org.jvnet.hudson.plugins.thinbackup.backup.BackupSet.initialize(BackupSet.java:93)
      	at org.jvnet.hudson.plugins.thinbackup.backup.BackupSet.<init>(BackupSet.java:79)
      	at org.jvnet.hudson.plugins.thinbackup.utils.Utils.getValidBackupSetsFromZips(Utils.java:353)
      	at org.jvnet.hudson.plugins.thinbackup.utils.Utils.getValidBackupSets(Utils.java:372)
      	at org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup.removeSuperfluousBackupSets(HudsonBackup.java:498)
      	at org.jvnet.hudson.plugins.thinbackup.backup.HudsonBackup.backup(HudsonBackup.java:178)
      	at org.jvnet.hudson.plugins.thinbackup.ThinBackupPeriodicWork.backupNow(ThinBackupPeriodicWork.java:89)
      	at org.jvnet.hudson.plugins.thinbackup.ThinBackupPeriodicWork.execute(ThinBackupPeriodicWork.java:70)
      	at org.jvnet.hudson.plugins.thinbackup.hudson.model.AsyncPeriodicWork$1.run(AsyncPeriodicWork.java:53)
      	at java.lang.Thread.run(Thread.java:748)
      
      Mar 05, 2018 1:42:26 AM WARNING org.jvnet.hudson.plugins.thinbackup.backup.BackupSet 
      Could not initialize backup set from file/directory 'BACKUPSET_2018-02-26_01-00_2018-03-04_01-00.zip' as it is not valid.
      Mar 05, 2018 2:47:38 AM INFO org.jvnet.hudson.plugins.thinbackup.utils.Utils moveOldBackupsToZipFile
      DONE moving 1 backup set(s) to ZIP files.
      

      It took almost three hours. Is that right? Also please notice those ThinBackup Worker Thread thread is still running. Execution aborted. warnings. I have them from the beggining of using thinBackup. There is another issue I linked to this one.

       

       

       

       

        Attachments

          Issue Links

            Activity

            There are no comments yet on this issue.

              People

              • Assignee:
                tofuatjava Thomas Fürer
                Reporter:
                ewypych Emil Wypych
              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated: