GnuPG passphrase error after failed backup session

Bug #946988 reported by Daniel Andersson on 2012-03-05
116
This bug affects 22 people
Affects Status Importance Assigned to Milestone
Duplicity
Medium
Unassigned
duplicity (Ubuntu)
Undecided
Unassigned
Precise
Medium
Unassigned

Bug Description

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

Related branches

Daniel Andersson (drandersson) wrote :
smu (smu) wrote :

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) wrote :

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) wrote :

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) wrote :
Download full text (3.3 KiB)

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...

Read more...

LKRaider (paul-eipper) wrote :

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

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).

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) wrote :

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) wrote :

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) wrote :

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

spi (spi-gmxpro) wrote :

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) wrote :

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

It sounds reasonable to me.

Changed in duplicity:
importance: Undecided → Medium
status: New → Fix Committed
Changed in duplicity:
milestone: none → 0.6.21
Randy Fay (randyfay) wrote :

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

Randy Fay (randyfay) wrote :

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

Changed in duplicity:
status: Fix Committed → Fix Released
Louis Bouchard (louis) on 2014-01-24
Changed in duplicity (Ubuntu Precise):
status: New → In Progress
importance: Undecided → Medium
assignee: nobody → Louis Bouchard (louis-bouchard)
Louis Bouchard (louis) wrote :

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

Changed in duplicity (Ubuntu):
status: New → Fix Released
Henning Sprang (henning) wrote :

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) wrote :

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

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!

Changed in duplicity (Ubuntu Precise):
status: In Progress → Fix Committed
tags: added: verification-needed
Louis Bouchard (louis) on 2014-03-31
tags: added: verification-done
removed: verification-needed
Launchpad Janitor (janitor) wrote :

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

Changed in duplicity (Ubuntu Precise):
status: Fix Committed → Fix Released

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.

Louis Bouchard (louis) on 2014-04-11
Changed in duplicity (Ubuntu Precise):
assignee: Louis Bouchard (louis-bouchard) → nobody
kangus (kangus) wrote :

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

Chet Wisniewski (chetw) wrote :

I am also seeing this in 0.6.24 on Arch Linux

Bill (will-yager) wrote :

I am seeing this bug in 0.6.24 on OS X.

Bill (will-yager) wrote :

Note for posterity: adding the

 --use-agent

switch seems to fix the issue.

Boyan Penkov (boyan-penkov) wrote :

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

Artur Bodera (abodera) wrote :

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) wrote :

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) wrote :

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 =====

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

Other bug subscribers

Related questions