Duplicity

gpg: fatal: zlib inflate problem: incorrect data check

Bug #713832 reported by William Deninger
14
This bug affects 3 people
Affects Status Importance Assigned to Milestone
Duplicity
New
Undecided
Unassigned

Bug Description

duplicity 0.6.11
Python 2.6.5
Linux SOUTH 2.6.32-27-generic #49-Ubuntu SMP Thu Dec 2 00:51:09 UTC 2010 x86_64 GNU/Linux

This has been an issue for some time (pre 0.6.8b through 0.6.11).

I create the incident by performing a full backup of a data repository path to a mounted drive on the same system. The failure is produced when attempting to verify, restore or file restore the specific file which fails.

Repository backup call:
nohup duplicity --encrypt-key "8ABB1A41" --sign-key "8ABB1A41" --verbosity 9 "/media/MadDog/Archive/" "file:///media/Poodle/backup/media/MadDog/Archive/" >> localbackup.log &

No errors or warnings are issued during the backup phase:

AsyncScheduler: running task synchronously (asynchronicity disabled)
Writing /media/Poodle/backup/./media/Poodle/Archive.dup/Photo Archive/duplicity-full.20100902T170354Z.vol1147.difftar.gpg
Deleting /tmp/duplicity-X5gfOu-tempdir/mktemp-CVCWXz-1148
Forgetting temporary file /tmp/duplicity-X5gfOu-tempdir/mktemp-CVCWXz-1148
AsyncScheduler: task completed successfully
Processed volume 1147
Registering (mktemp) temporary file /tmp/duplicity-X5gfOu-tempdir/mktemp-RGVAhj-1149
AsyncScheduler: running task synchronously (asynchronicity disabled)
Writing /media/Poodle/backup/./media/Poodle/Archive.dup/Photo Archive/duplicity-full.20100902T170354Z.vol1148.difftar.gpg
Deleting /tmp/duplicity-X5gfOu-tempdir/mktemp-RGVAhj-1149
Forgetting temporary file /tmp/duplicity-X5gfOu-tempdir/mktemp-RGVAhj-1149
AsyncScheduler: task completed successfully
Processed volume 1148
Registering (mktemp) temporary file /tmp/duplicity-X5gfOu-tempdir/mktemp-Vk9ex8-1150
AsyncScheduler: running task synchronously (asynchronicity disabled)
Writing /media/Poodle/backup/./media/Poodle/Archive.dup/Photo Archive/duplicity-full.20100902T170354Z.vol1149.difftar.gpg
Deleting /tmp/duplicity-X5gfOu-tempdir/mktemp-Vk9ex8-1150
Forgetting temporary file /tmp/duplicity-X5gfOu-tempdir/mktemp-Vk9ex8-1150
AsyncScheduler: task completed successfully
Processed volume 1149
.
.
.
File duplicity-full.20110205T061747Z.vol3671.difftar.gpg is part of known set
Found backup chain [Fri Feb 4 22:17:47 2011]-[Fri Feb 4 22:17:47 2011]
--------------[ Backup Statistics ]--------------
StartTime 1296886667.37 (Fri Feb 4 22:17:47 2011)
EndTime 1296901383.13 (Sat Feb 5 02:23:03 2011)
ElapsedTime 14715.76 (4 hours 5 minutes 15.76 seconds)
SourceFiles 50598
SourceFileSize 129262183781 (120 GB)
NewFiles 50598
NewFileSize 129262183781 (120 GB)
DeletedFiles 0
ChangedFiles 0
ChangedFileSize 0 (0 bytes)
ChangedDeltaSize 0 (0 bytes)
DeltaEntries 50598
RawDeltaSize 129247782245 (120 GB)
TotalDestinationSizeChange 125396358454 (117 GB)
Errors 0
-------------------------------------------------

Removing still remembered temporary file /tmp/duplicity-ll_k8Z-tempdir/mkstemp-fl_3D4-1

During verify, restore and file restore, the following occurs which terminates the restore process:

nohup duplicity restore --encrypt-key 8ABB1A41 --sign-key 8ABB1A41 --ignore-errors --verbosity 9 "file:///media/Poodle/backup/media/MadDog/Archive/" "/media/Poodle/restore/" > localrestore.log &

OR

duplicity --encrypt-key 8ABB1A41 --sign-key 8ABB1A41 --verbosity debug --file-to-restore "Photo Archive/1995/19950817 Fort Lauderdale 08.jpg" "file:///media/Poodle/backup/media/MadDog/Archive/" "/media/Poodle/restore2.jpg/" > duplicity-failure.log

where the file "Archive/1995/19950817 Fort Lauderdale 08.jpg" is the failing restore.

Running in 'ignore errors' mode due to --ignore-errors; please re-consider if this was not intended
Using archive dir: /root/.cache/duplicity/0543e0fc57cd727701c014cdcfc1718f
Using backup name: 0543e0fc57cd727701c014cdcfc1718f
Import of duplicity.backends.imapbackend Succeeded
Import of duplicity.backends.webdavbackend Succeeded
Import of duplicity.backends.sshbackend Succeeded
Import of duplicity.backends.rsyncbackend Succeeded
Import of duplicity.backends.tahoebackend Succeeded
Import of duplicity.backends.localbackend Succeeded
Import of duplicity.backends.giobackend Succeeded
Import of duplicity.backends.hsibackend Succeeded
Import of duplicity.backends.botobackend Succeeded
Import of duplicity.backends.cloudfilesbackend Succeeded
Import of duplicity.backends.ftpbackend Succeeded
Main action: restore
================================================================================
duplicity 0.6.11 (November 20, 2010)
Args: /usr/local/bin/duplicity restore --encrypt-key 8ABB1A41 --sign-key 8ABB1A41 --ignore-errors --verbosity 9 file:///media/Poodle/backup//media/MadDog/Archive// /media/Poodle/restore/
Linux SOUTH 2.6.32-27-generic #49-Ubuntu SMP Thu Dec 2 00:51:09 UTC 2010 x86_64
/usr/bin/python 2.6.5 (r265:79063, Apr 16 2010, 13:57:41)
[GCC 4.4.3]
================================================================================
Using temporary directory /tmp/duplicity-ku5lKg-tempdir
Registering (mkstemp) temporary file /tmp/duplicity-ku5lKg-tempdir/mkstemp-MP77AK-1
Temp has 136185794560 available, backup will use approx 34078720.
Synchronizing remote metadata to local cache...
Copying duplicity-full-signatures.20110205T061747Z.sigtar to local cache.
Registering (mktemp) temporary file /tmp/duplicity-ku5lKg-tempdir/mktemp-stjUrp-2
Deleting /tmp/duplicity-ku5lKg-tempdir/mktemp-stjUrp-2
Forgetting temporary file /tmp/duplicity-ku5lKg-tempdir/mktemp-stjUrp-2
Copying duplicity-full.20110205T061747Z.manifest to local cache.
Registering (mktemp) temporary file /tmp/duplicity-ku5lKg-tempdir/mktemp-orBhm3-3
Deleting /tmp/duplicity-ku5lKg-tempdir/mktemp-orBhm3-3
Forgetting temporary file /tmp/duplicity-ku5lKg-tempdir/mktemp-orBhm3-3
4776 files exist on backend
2 files exist in cache
.
.
.
Writing Photo Archive/1995/19950817 Fort Lauderdale 07.jpg of type reg
Writing Photo Archive/1995/19950817 Fort Lauderdale 08.jpg of type reg
Removing still remembered temporary file /tmp/duplicity-ku5lKg-tempdir/mkstemp-MP77AK-1
Removing still remembered temporary file /tmp/duplicity-ku5lKg-tempdir/mktemp-VgFZYz-585
GPG error detail: Traceback (most recent call last):
  File "/usr/local/bin/duplicity", line 1245, in <module>
    with_tempdir(main)
  File "/usr/local/bin/duplicity", line 1238, in with_tempdir
    fn()
  File "/usr/local/bin/duplicity", line 1192, in main
    restore(col_stats)
  File "/usr/local/bin/duplicity", line 539, in restore
    restore_get_patched_rop_iter(col_stats)):
  File "/usr/local/lib/python2.6/dist-packages/duplicity/patchdir.py", line 522, in Write_ROPaths
    ITR( ropath.index, ropath )
  File "/usr/local/lib/python2.6/dist-packages/duplicity/lazy.py", line 335, in __call__
    last_branch.fast_process, args)
  File "/usr/local/lib/python2.6/dist-packages/duplicity/robust.py", line 37, in check_common_error
    return function(*args)
  File "/usr/local/lib/python2.6/dist-packages/duplicity/patchdir.py", line 575, in fast_process
    ropath.copy( self.base_path.new_index( index ) )
  File "/usr/local/lib/python2.6/dist-packages/duplicity/path.py", line 416, in copy
    other.writefileobj(self.open("rb"))
  File "/usr/local/lib/python2.6/dist-packages/duplicity/path.py", line 591, in writefileobj
    buf = fin.read(_copy_blocksize)
  File "/usr/local/lib/python2.6/dist-packages/duplicity/patchdir.py", line 200, in read
    if not self.addtobuffer():
  File "/usr/local/lib/python2.6/dist-packages/duplicity/patchdir.py", line 225, in addtobuffer
    self.tarinfo_list[0] = self.tar_iter.next()
  File "/usr/local/lib/python2.6/dist-packages/duplicity/patchdir.py", line 332, in next
    self.set_tarfile()
  File "/usr/local/lib/python2.6/dist-packages/duplicity/patchdir.py", line 320, in set_tarfile
    assert not self.current_fp.close()
  File "/usr/local/lib/python2.6/dist-packages/duplicity/dup_temp.py", line 210, in close
    assert not self.fileobj.close()
  File "/usr/local/lib/python2.6/dist-packages/duplicity/gpg.py", line 198, in close
    self.gpg_failed()
  File "/usr/local/lib/python2.6/dist-packages/duplicity/gpg.py", line 165, in gpg_failed
    raise GPGError, msg
GPGError: GPG Failed, see log below:
===== Begin GnuPG log =====
gpg: encrypted with 2048-bit RSA key, ID 73B4F60A, created 2010-09-02
"Firstname Lastname(Duplicity key) <email address hidden>"
gpg: fatal: zlib inflate problem: incorrect data check
secmem usage: 2624/5664 bytes in 6/16 blocks of pool 5856/32768
===== End GnuPG log =====

I am willing to provide access to the appropriate engineer if required. The bug has delayed me over a year from using Duplicity, but now that Mozy is jacking up their rates time to resolution is more critical.

Thanks,
-W

Revision history for this message
William Deninger (wdeninger) wrote :
Download full text (6.6 KiB)

When mod priviledges are modified back to a typical 755, the extracted file "19950817 Fort Lauderdale 08.jpg" appears (image wise) as the first 75% of he original file. The lower 25% of the image is missing. So it seems that the last portion of the file has not been extracted.

I have identified the volume containing the failure The offending file
"19950817 Fort Lauderdale 08.jpg" exists across the volume boundary, spans 19
segments from th last part of vol582 into vol583. The first volume (vol582) produces a gpg fatal error. The second volume (vol583) does not (see below).

gpg --decrypt /media/Poodle/backup/media/MadDog/Archive/duplicity-full.20110205T061747Z.vol582.difftar.gpg > duplicity.difftar

You need a passphrase to unlock the secret key for
user: "First Last(Duplicity key) <email address hidden>"
2048-bit RSA key, ID 73B4F60A, created 2010-09-02 (main key ID 8ABB1A41)

gpg: gpg-agent is not available in this session
gpg: encrypted with 2048-bit RSA key, ID 73B4F60A, created 2010-09-02
      "FIrst Last(Duplicity key) <email address hidden>"
gpg: fatal: zlib inflate problem: incorrect data check
secmem usage: 2400/5440 bytes in 5/15 blocks of pool 5632/32768

When duplicity-full.20110205T061747Z.vol582.difftar.gpg
 is decrypted and extracted, the volume snapshot appears as:

.
.
.
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 07.jpg/22
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 07.jpg/23
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 07.jpg/24
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 08.jpg/1
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 08.jpg/2
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 08.jpg/3
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 08.jpg/4
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 08.jpg/5
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 08.jpg/6
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 08.jpg/7
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 08.jpg/8
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 08.jpg/9
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 08.jpg/10
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 08.jpg/11
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 08.jpg/12
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 08.jpg/13
multivol_snapshot/Photo Archive/1995/19950817 Fort Lauderdale 08.jpg/14

The sequential volume duplicity-full.20110205T061747Z.vol583.difftar.gpg
(vol583):

gpg --decrypt /media/Poodle/backup/media/MadDog/Archive/duplicity-full.20110205T061747Z.vol583.difftar.gpg > duplicity.difftar

You need a passphrase to unlock the secret key for
user: "First Last(Duplicity key) <email address hidden>"
2048-bit RSA key, ID 73B4F60A, created 2010-09-02 (main key ID 8ABB1A41)

gpg: gpg-agent is not available in this session
gpg: encrypted with 2048-bit RSA key, ID 73B4F60A, created 2010-09-02
      "First Last(Duplicity key) <email address hidden>"
gpg: Signature made Fri 04 Feb 2011 10:50:42 PM PST using RSA ...

Read more...

Revision history for this message
William Deninger (wdeninger) wrote :

Additional information: using

zlib-1.2.5
gpg-1.4.11

Revision history for this message
William Deninger (wdeninger) wrote :

After reencrypting the complaining duplicity volume and verifying that it no longer produced a gpg decription failure, I proceeded to re-attempt the duplicity restore.

But unfortunately, since gpg includes a seed which results in a different hash anytime an encryptis performed, the manifest hash and calculated hash differ resulting in yet another failure (at exactly the same volume and file).

Revision history for this message
William Deninger (wdeninger) wrote :

After considerable testing and hair pulling, I have come to the conclusion that the problem I've been experiencing has a good chance of residing in gpg having problems operating on a 64-bit AMD system running Ubuntu.

As a last ditch effort, I attempted a full backup and restore of the same file archive through a smb mount from an old Intel P4 32bit dual core system, and it competed without incident. Given the time and energy wasted, I'm now prepared to pitch my AMD system into the fireplace.

-W

Revision history for this message
William Deninger (wdeninger) wrote :

I performed a fresh re-installation of duplicity on the AMD 64bit Ubuntu machine and experienced my first successful backup (47k files, 127GB). Since I have done nothing to solve the problem, I can only suspect I will have the problem occur again at a later time.

The corruption definitely occurs during the backup phase, because multiple attempts at restoring the same a backup duplicity archive fails identically. Each attempt at creating a new backup duplicity archive results in a different point of corruption during the subsequent restore process.

The system I used is an AMD 64-bit running Ubuntu. Because of the zlib compression failures, I had modified the gpg source to use the latest zlib library (as opposed to the version with known exploits shipped within the code itself). Also, the target dest and src duplicity drives are local USB hard drives. This may be important if file flushing/syncing is managed differently from the kernel OS -- I had been suspecting a race condition that upon the gpg thread termination the output stream had not flushed, and the subsequent thread execution of md5/sha produced a signature over less than the entire file. If I experience the md5/sha mismatch again, I will perform a byte by byte reconstruction of the file signature to see if the incorrect signature exists within the original file.

-W

Revision history for this message
Patrick Allemann (pallemann) wrote :

Hi there..

I ran into the same error:

gpg: fatal: zlib inflate problem: invalid stored block lengths
secmem usage: 2336/2720 bytes in 5/9 blocks of pool 3904/32768

and I am on a debian system (lenny 2.6.26-2-amd64)

GPG error detail: Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1245, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1238, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1139, in main
    sync_archive()
  File "/usr/bin/duplicity", line 953, in sync_archive
    copy_to_local(fn)
  File "/usr/bin/duplicity", line 913, in copy_to_local
    size=sys.maxint)
  File "/usr/lib/python2.5/site-packages/duplicity/gpg.py", line 331, in GzipWriteFile
    new_block = block_iter.next(min(128*1024, bytes_to_go))
  File "/usr/bin/duplicity", line 894, in next
    self.fileobj.close()
  File "/usr/lib/python2.5/site-packages/duplicity/dup_temp.py", line 210, in close
    assert not self.fileobj.close()
  File "/usr/lib/python2.5/site-packages/duplicity/gpg.py", line 198, in close
    self.gpg_failed()
  File "/usr/lib/python2.5/site-packages/duplicity/gpg.py", line 165, in gpg_failed
    raise GPGError, msg
GPGError: GPG Failed, see log below:
===== Begin GnuPG log =====
gpg: encrypted with 1024-bit ELG-E key, ID 752CCE08, created 2010-12-23
"sn56482 (Swissnas Customer sn56482 Key)"
gpg: fatal: zlib inflate problem: invalid stored block lengths
secmem usage: 2336/2720 bytes in 5/9 blocks of pool 3904/32768
===== End GnuPG log =====

GPGError: GPG Failed, see log below:
===== Begin GnuPG log =====
gpg: encrypted with 1024-bit ELG-E key, ID 752CCE08, created 2010-12-23
"masked"
gpg: fatal: zlib inflate problem: invalid stored block lengths
secmem usage: 2336/2720 bytes in 5/9 blocks of pool 3904/32768
===== End GnuPG log =====

11:09:38.043 Task 'BKP' failed with exit code '31'.
--- Finished state FAILED 'code 31' at 11:09:38.043 - Runtime 00:09:32.317 ---

Looks as if one of the files which is being downloaded by duplicity cannot be decompressed... If I could figure out which it is I could delete it on the server and duplicity would at least carry on backupping.
Did you find a workaround?

Revision history for this message
Patrick Allemann (pallemann) wrote :

It was the latest signature file which was uploaded. For some reasons it did not deflate properly. I deleted the complete last run from the target and everything is running smoothly again.

Revision history for this message
Stephan Walter (stephan-walter) wrote :

I have been using deja-dup successfully for some time. Since a few days ago, backups started failing with the following error message:

GPGError: GPG Failed, see log below:
===== Begin GnuPG log =====
gpg: WARNING: "--no-use-agent" is an obsolete option - it has no effect
gpg: AES256 encrypted data
gpg: encrypted with 1 passphrase
gpg: Fatal: zlib inflate problem: invalid stored block lengths
===== End GnuPG log =====

The client/source is a 64 bit ubuntu with Intel processor. Possibly relevant package versions:

ii deja-dup 37.1-2fakesync1ubuntu0.1 amd64 Backup utility
ii duplicity 0.7.17-0ubuntu1.1 amd64 encrypted bandwidth-efficient backup
ii gpg 2.2.4-1ubuntu1.2 amd64 GNU Privacy Guard -- minimalist public key operations
ii gpg-agent 2.2.4-1ubuntu1.2 amd64 GNU privacy guard - cryptographic agent
ii gpg-wks-client 2.2.4-1ubuntu1.2 amd64 GNU privacy guard - Web Key Service client
ii gpg-wks-server 2.2.4-1ubuntu1.2 amd64 GNU privacy guard - Web Key Service server
ii gpgconf 2.2.4-1ubuntu1.2 amd64 GNU privacy guard - core configuration utilities
ii gpgsm 2.2.4-1ubuntu1.2 amd64 GNU privacy guard - S/MIME version
ii gpgv 2.2.4-1ubuntu1.2 amd64 GNU privacy guard - signature verification tool
ii openssh-client 1:7.6p1-4ubuntu0.3 amd64 secure shell (SSH) client, for secure access to remote machines

The server/destination is a Raspberry Pi with Raspbian. Possibly relevant package versions:

ii openssh-server 1:7.4p1-10+deb9u6 armhf secure shell (SSH) server, for secure access from remote machines
ii openssh-sftp-server 1:7.4p1-10+deb9u6 armhf secure shell (SSH) sftp server module, for SFTP access from remote machines

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.