GnuPG passphrase error after failed backup session

[Daniel Andersson]

After a failed backup session, duplicity cannot resume the volume creation, and seems to fail with "bad passphrase". It is, however, the same passphrase that is always used.

The backup set thus seems to be unusable, and the only solution I've found is to simply create a new backup set in a new directory, losing incremental history.

Full output attached as "duplicity-error-incremental-log-v9".

Also reported as Debian bug #659009, but it has gotten no attention for a month.

Duplicity 0.6.17
Python 2.7.2+
Debian Sid
Linux

[smu (smu)]

same error on arch linux using version 0.6.18-2.

a possible solution is proposed here https://answers.launchpad.net/duplicity/+question/183711

[max (max-warped)]

I'm seeing the same behavior as the above thread. Using duplicity-0.6.18.tar.gz compiled on centos 5.7.
Reverting the "#11" patch from the thread above lets the backup begin its "resume" but it still fails at the very end.

I'm using keychain (latest) + gpg-agent. It appears that gpg-agent "forgets" my key after a while. I am not sending it any SIGHUPs or giving it any other reason to forget.

[max (max-warped)]

AsyncScheduler: instantiating at concurrency 0
GPG error detail: Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1391, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1384, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1354, in main
    full_backup(col_stats)
  File "/usr/bin/duplicity", line 500, in full_backup
    globals.backend)
  File "/usr/bin/duplicity", line 378, in write_multivol
    globals.gpg_profile, globals.volsize)
  File "/usr/lib/python2.6/site-packages/duplicity/gpg.py", line 324, in GPGWriteFile
    file.write(data)
  File "/usr/lib/python2.6/site-packages/duplicity/gpg.py", line 185, in write
    self.gpg_failed()
  File "/usr/lib/python2.6/site-packages/duplicity/gpg.py", line 206, in gpg_failed
    raise GPGError, msg
GPGError: GPG Failed, see log below:
===== Begin GnuPG log =====
gpg: cancelled by user
gpg: no default secret key: bad passphrase
gpg: [stdin]: sign+encrypt failed: bad passphrase
===== End GnuPG log =====

GPGError: GPG Failed, see log below:
===== Begin GnuPG log =====
gpg: cancelled by user
gpg: no default secret key: bad passphrase
gpg: [stdin]: sign+encrypt failed: bad passphrase
===== End GnuPG log =====

Duplicity Exited with Error.

[max (max-warped)]

I upgraded gnupg to it's latest and the error message changed slightly :

AsyncScheduler: instantiating at concurrency 0
GPG error detail: Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1391, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1384, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1354, in main
    full_backup(col_stats)
  File "/usr/bin/duplicity", line 500, in full_backup
    globals.backend)
  File "/usr/bin/duplicity", line 378, in write_multivol
    globals.gpg_profile, globals.volsize)
  File "/usr/lib/python2.6/site-packages/duplicity/gpg.py", line 324, in GPGWriteFile
    file.write(data)
  File "/usr/lib/python2.6/site-packages/duplicity/gpg.py", line 185, in write
    self.gpg_failed()
  File "/usr/lib/python2.6/site-packages/duplicity/gpg.py", line 206, in gpg_failed
    raise GPGError, msg
GPGError: GPG Failed, see log below:
===== Begin GnuPG log =====
gpg: problem with the agent - disabling agent use
gpg: can't query passphrase in batch mode
gpg: Invalid passphrase; please try again ...
gpg: can't query passphrase in batch mode
gpg: Invalid passphrase; please try again ...
gpg: can't query passphrase in batch mode
gpg: no default secret key: bad passphrase
gpg: [stdin]: sign+encrypt failed: bad passphrase
===== End GnuPG log =====

GPGError: GPG Failed, see log below:
===== Begin GnuPG log =====
gpg: problem with the agent - disabling agent use
gpg: can't query passphrase in batch mode
gpg: Invalid passphrase; please try again ...
gpg: can't query passphrase in batch mode
gpg: Invalid passphrase; please try again ...
gpg: can't query passphrase in batch mode
gpg: no default secret key: bad passphrase
gpg: [stdin]: sign+encrypt failed: bad passphrase
===== End GnuPG log =====

Duplicity Exited with Error.

So I ran gpg-agent with --log and --verbose and I'm seeing this error which looks promising in tracking down the problem :

2012-03-19 11:18:22 gpg-agent[20679] listening on socket `/tmp/gpg-l4u3W8/S.gpg-agent'
2012-03-19 11:18:22 gpg-agent[20680] gpg-agent (GnuPG) 2.0.18 started
2012-03-19 11:18:22 gpg-agent[20680] handler 0x656b30 for fd 7 started
2012-03-19 11:18:22 gpg-agent[20680] starting a new PIN Entry
2012-03-19 11:18:22 gpg-agent[20680] You may want to update to a newer pinentry
2012-03-19 11:18:28 gpg-agent[20680] handler 0x656b30 for fd 7 terminated
2012-03-19 11:18:29 gpg-agent[20680] handler 0x656b30 for fd 7 started
2012-03-19 11:18:29 gpg-agent[20680] handler 0x656b30 for fd 7 terminated
2012-03-19 11:18:46 gpg-agent[20680] handler 0x656b30 for fd 7 started
2012-03-19 11:18:46 gpg-agent[20680] handler 0x656b30 for fd 7 terminated
2012-03-19 11:25:10 gpg-agent[20680] handler 0x656b30 for fd 7 started
2012-03-19 11:25:10 gpg-agent[20680] handler 0x656b30 for fd 7 terminated
2012-03-19 11:35:58 gpg-agent[20680] handler 0x656b30 for fd 7 started
2012-03-19 11:35:58 gpg-agent[20680] starting a new PIN Entry
2012-03-19 11:35:58 gpg-agent[20680] You may want to update to a newer pinentry
2012-03-19 11:35:58 gpg-agent[20680] command get_passphrase failed: Invalid card
2012-03-19 11:35:58 gpg-agent[20680] handler 0x656b30 for fd 7 terminated

The midd...

[LKRaider (paul-eipper)]

Using duplicity 0.6.19 and seeing this issue

* Not using gpg-agent
* Exporting PASSPHRASE on script that runs duplicity
* Sign and encryption keys are the same

```
Reading globbing filelist offsite-backup.list
Local and Remote metadata are synchronized, no sync needed.
Last full backup left a partial set, restarting.
Last full backup date: Wed Jul 11 16:39:03 2012
Reuse configured PASSPHRASE as SIGN_PASSPHRASE
RESTART: Volumes 35 to 35 failed to upload before termination.
         Restarting backup at volume 35.
GPGError: GPG Failed, see log below:
===== Begin GnuPG log =====
gpg: encrypted with 2048-bit RSA key, ID 49A09DC2, created 2012-07-11
"Backup (Encryption key for backups) <*obfuscated*@*obfuscated*.com>"
gpg: public key decryption failed: bad passphrase
gpg: decryption failed: secret key not available
===== End GnuPG log =====
```

GnuPG version 1.4.12 on Mac OSX Lion 10.7.4

[Brock Spratlen (mail-wz6bkyhu4uqpfausw0ege9b0y33ege6o4wzvqwe1gy11y)]

I have also encountered this issue. I am not using gpg-agent; I have a wrapper shell script that exports the PASSPHRASE environment variable before calling duplicity. I am using the same GPG key for both signing and encrypting.

My environment is as follows:

OS: Ubuntu 10.04 32-bit
GnuPG: 1.4.10
Duplicity: 0.6.19

Verbose logfile is attached (via duplicity -v9).

[Brock Spratlen (mail-wz6bkyhu4uqpfausw0ege9b0y33ege6o4wzvqwe1gy11y)]

I believe that I have figured out what is going wrong, at least at a rudimentary level. I'm very unfamiliar with the codebase, so take this with a grain of salt (please).

I injected a bunch of print statements all over, focusing on the stack trace from the error output. This didn't particularly help until I printed the contents of "global.gpg_profile.passphrase" in the body of the validate_encryption_settings function: it was blank. I added another print statement immediately before to ensure that the python process had the proper environment variables (i.e. print(os.environ['PASSPHRASE'])): the passphrase was present in os.environ as expected.

It appears that the main duplicity python script does not try to load global.gpg_profile.passphrase if the backup type is "full" or "inc" (per lines 1313 of bin/duplicity):

    # full/inc only needs a passphrase for symmetric keys
    if not action in ["full", "inc"] or not globals.gpg_profile.recipients:
        # get the passphrase if we need to based on action/options
        globals.gpg_profile.passphrase = get_passphrase(1, action)

I think this conflicts with the new functionality introduced by validate_encryption_settings, as it is essentially verifying the first volume to ensure the encryption keys are correct.

So, a "full" backup doesn't load a value in globals.gpg_profile.passphrase, but if the last backup was found to be partial, validate_encryption_settings gets called, which leads to an operation (file read? gpg initialization?) that requires globals.gpg_profile.passphrase to be set. Hence GPG's complaint.

I've attached a patch that solves this issue for me, but I have no idea how it will affect other usage scenarios. The patch just adds a few lines in validate_encryption_settings to load globals.gpg_profile.passphrase if it hasn't been loaded already. Feels, hacky, but it's working for now.

Hope that helps!

[Michael Terry (mterry)]

I wrote that validate_encryption_settings function, so sorry folks if I messed things up.

Brock, thank you for the analysis, it's very helpful. But I share your suspicions that your patch is attacking the root cause.

The two logs given use both encrypt and sign keys. I'm a little unclear how keys work in duplicity (I usually use symmetric encryption), but I believe that while the encrypt key does not need a passphrase, the sign key does?

If that's the case, then the following line:

    if not action in ["full", "inc"] or not globals.gpg_profile.recipients:

should become:

    if not action in ["full", "inc"] or not globals.gpg_profile.recipients or globals.gpg_profile.sign_key:

to match the logic in get_passphrase. Or even better yet, just drop that if condition and always call get_passphrase, since it has the logic to be a no-op in those conditions. No reason to duplicate them.

Ken, does that make sense?

[edso (ed.so)]

just a side note.

sign key has it's own SIGN_PASSPHRASE env var since a while.

generally i would agree and set the global vars always when the corresponding env var or parameters were given.

..ede/duply.net

[scnaifeh (scnaifeh)]

Brock's patch worked for me, saving having to redo a 24 hour backup that was almost finished.

[spi (spi-gmxpro)]

Changing the "if not action in ["full", "inc"]..." statement as in #9 described did it for me.

I'm on Ubuntu 12.04 with duplicity 0.6.18, duply 1.5.5.4 and gpg 1.4.11.

[Michael Terry (mterry)]

Ken, poke about the reasoning in comment 9. Does that sound reasonable?

[Kenneth Loafman (kenneth-loafman)]

It sounds reasonable to me.

[Randy Fay (randyfay)]

Could we get this added to the <a href="https://launchpad.net/~duplicity-team/+archive/ppa">PPA</a>?

[Randy Fay (randyfay)]

I confirm the fix; once I used bzr to check out the latest and build it, I was OK.

[Louis Bouchard (louis)]

The backport of this fix to precise has been submitted for SRU with other fixes in Bug: #1266763

[Henning Sprang (henning)]

Seems to me this thing is not completely fix as of duplicity 0.6.21-0ubuntu4.1 in saucy, and I just lost a backup on a remote machine that took 2 days to build up, then was broken/undecryptable with the same messages and symptoms as found in this bug here, and I even unintentionally deleted the whole big data transfer that took two days by trying to repair it somehow with the "cleanup" command.

Let me know if you need any information that helps fixing this thing, or analyzing why it still happens here.

[Brian Murray (brian-murray)]

@Henning - you'll want the version of the package from saucy-proposed see bug 1266753.

[Brian Murray (brian-murray)]

Hello phz_swe, or anyone else affected,

Accepted duplicity into precise-proposed. The package will build now and be available at http://launchpad.net/ubuntu/+source/duplicity/0.6.18-0ubuntu3.5 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Launchpad Janitor (janitor)]

This bug was fixed in the package duplicity - 0.6.18-0ubuntu3.5

---------------
duplicity (0.6.18-0ubuntu3.5) precise; urgency=low

  * debian/patches/14-lp946988-fix-gnupassphrase-error.dpatch
    - Backport upstream modification applied in LP: #946988 that fix
      a failure to resume a backup with "bad passphrase" when the proper
      passphrase is being used.

  * debian/patches/13-lp1266763-add-concurrency-locking.dpatch
    - Implement locking mechanism to avoid concurrent execution under the same
      cache directory. This functionality adds a dependency to python-lockfile
      Fixes LP: #1266763

  * debian/patches/12-lp1266753-exception-if-no-s3.dpatch
    - Add exception handling in the case where no S3 connection is
      available instead of silently deleting the local cache.
      Fixes LP: #1266753
 -- Louis Bouchard <email address hidden> Thu, 23 Jan 2014 10:16:32 +0100

[Brian Murray (brian-murray)]

The verification of the Stable Release Update for duplicity has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regresssions.

[kangus (kangus)]

i am also suffering from this bug, in releases 0.6.21, 0.6.22, 0.6.23

[Chet Wisniewski (chetw)]

I am also seeing this in 0.6.24 on Arch Linux

[Bill (will-yager)]

I am seeing this bug in 0.6.24 on OS X.

[Bill (will-yager)]

Note for posterity: adding the

 --use-agent

switch seems to fix the issue.

[Boyan Penkov (boyan-penkov)]

--use-agent does not work for me -- any suggestions? I'm on 0.6.25

[Artur Bodera (abodera)]

I'm seeing this with duplicity 0.7.04 on OSX, using onedrive backend.
Unable to resume backup.
--use-agent doesn't help
No password prompt appears, backup just fails.

[Boyan Penkov (boyan-penkov)]

I'm seeing this with 0.7.02 as well, also on OS X. I am *not* seeing this with 0.6.24 on Debian stable; this leads me to think this is an issue with:

1) OS X or
2) how duplicity talks to gpg-agent on OS X

[ser (seanerussell)]

Same error here:

duplicity 0.7.01
gpg (GnuPG) 1.4.18
Ubuntu 15.04
Python 2.7.9

/usr/bin/duplicity incremental \
       # Many --excludes
        --tempdir=/tmp \
        --encrypt-key 09E5788F \
        --use-agent \
        $HOME file://${HOME}/Network/DIMHOLT/Data

eventually results in:

Copying duplicity-full-signatures.20150805T004551Z.sigtar.gpg to local cache.
Attempt 1 failed. IOError: [Errno 5] Input/output error
GPGError: GPG Failed, see log below:
===== Begin GnuPG log =====
gpg: cancelled by user
gpg: encrypted with 2048-bit ELG-E key, ID DCFE3A67, created 2013-07-06
"XXX XXX <email address hidden>"
gpg: public key decryption failed: bad passphrase
gpg: decryption failed: secret key not available
===== End GnuPG log =====