Improve error handling if user cancels the decryption operation about passff HOT 18 OPEN

PassFF doesn't know that the user has deliberately canceled the decryption. We could check for "Operation cancelled" in the error output, but this won't work for users with non-english localization settings.

from passff.

A lot more research would be needed but it seems like it might be plausible to extract machine-readable error codes using the --status-file flag. @bkazez would have to confirm whether this flag even exists on Mac, but I did this:

# kill my existing session
killall gpg-agent
# try to decrypt some throwaway thing, cancel the pinentry
PASSWORD_STORE_GPG_OPTS=--status-file=/tmp/canc.txt pass temp
# try to decrypt some throwaway thing, get the passphrase wrong three times
PASSWORD_STORE_GPG_OPTS=--status-file=/tmp/badpw.txt pass temp
# try to decrypt something I deliberately encrypted for a secret key I don't have
PASSWORD_STORE_GPG_OPTS=--status-file=/tmp/impossible.txt pass unreadable

and I got distinctly different logs in each of those temp files, all machine-parseable.

"Operation Canceled" had this in it:

[GNUPG:] ERROR pkdecrypt_failed 83886179

"Bad Passphrase" had this in it:

[GNUPG:] ERROR pkdecrypt_failed 67108875

And the impossible file did NOT have a line beginning with

[GNUPG:] KEY_CONSIDERED <Redacted> 0

This seems like a plausible way forward, but also a confusing one, since of course none of those numeric error codes looks anything like the declared libgpg error codes. One would have to take a dive into the gpg source code to figure out where those codes are coming from and whether they're predictable enough to be relied upon. A second person trying this on a different gpg version (I have 2.2.41, but fc users will have something much newer and ubuntu users will have something much older) would at least be a helpful experiment.

from passff.

I get the same values as you!

"Operation Canceled"

[GNUPG:] ERROR pkdecrypt_failed 83886179

"Bad Passphrase"

[GNUPG:] ERROR pkdecrypt_failed 67108875

for a secret key I don't have

[GNUPG:] KEY_CONSIDERED
...
[GNUPG:] ERROR pkdecrypt_failed 33554449

from passff.

The meaning of these values is documented in libgpg-error, so it should be possible to make meaning of these error codes.

 * An error code together with an error source build up an error
 * value.  As the error value is been passed from one component to
 * another, it preserves the information about the source and nature
 * of the error.

from passff.

And sure enough &ing with the value of GPG_ERR_CODE_MASK does result in recognizable codes from the lookup table.

>>> codes = (67108875, 83886179, 33554449)
>>> [c & 0xFFFF for c in codes]
[11, 99, 17]

Or, GPG_ERR_BAD_PASSPHRASE, GPG_ERR_CANCELED, and GPG_ERR_NO_SECKEY, respectively.

from passff.

I started trying to hack this into passff_host.py just to see how difficult it'd be, and I am left with a fairly baffling situation. On two different computers with the same operating system and same gpg version, I do not see the ERROR pkdecrypt_failed message in the --status-file. It turns out the code that emits this is gated by this if statement and --quiet is injected by pass itself.

What makes this baffling is, as far as I know my work computer (from which I was reporting all those hopeful results this morning) is configured identically to my personal laptop. ArchLinux, fully updated, gnupg 2.2.41. I don't get it. But it does seem that at the very least the presence of this error string is not reliable.

I compiled gnupg 2.2.41 from source with debug symbols in it so I could confirm this hypothesis. When --quiet is not present, here's the stack trace of it emitting that message:

Breakpoint 1, print_pkenc_list (ctrl=0x5555556ac7b0, list=0x5555556b87e0, 
    failed=1) at mainproc.c:666
666	          write_status_error ("pkdecrypt_failed", list->reason);
(gdb) bt
#0  print_pkenc_list (ctrl=0x5555556ac7b0, list=0x5555556b87e0, failed=1)
    at mainproc.c:666
#1  0x0000555555599c91 in proc_encrypted (c=0x5555556ac880, 
    pkt=0x5555556ac6b0) at mainproc.c:697
#2  0x000055555559c3d5 in do_proc_packets (ctrl=0x5555556ac7b0, 
    c=0x5555556ac880, a=0x5555556ac7f0) at mainproc.c:1721
#3  0x000055555559bf95 in proc_encryption_packets (ctrl=0x5555556ac7b0, 
    anchor=0x0, a=0x5555556ac7f0) at mainproc.c:1612
#4  0x00005555555cce50 in decrypt_message (ctrl=0x5555556ac7b0, 
    filename=0x7fffffffe777 "/home/drmoose/.password-store/temp.gpg")
    at decrypt.c:89
#5  0x000055555556c237 in main (argc=1, argv=0x7fffffffe338) at gpg.c:4380

And here it is with --quiet set:

Breakpoint 1, proc_encrypted (c=0x5555556ac880, pkt=0x5555556ac6b0)
    at mainproc.c:691
691	  if (!opt.quiet)
(gdb) p opt.quiet
$1 = 1

--quiet can be forced back off by adding --debug=crypto to $PASSWORD_STORE_GNUPG_OPTS but that also makes the stderr output we already rely on much, much longer.

gpg: reading options from '[cmdline]'
gpg: enabled debug flags: crypto
gpg: enabled compatibility flags:
gpg: public key is <Redacted>
gpg: using subkey <Redacted> instead of primary key <Redacted>
gpg: pinentry launched (189509 gtk2 1.2.1 /dev/pts/0 xterm-256color :0 20620/1000/5 1000/1000 0)
gpg: using subkey <Redacted> instead of primary key <Redacted>
gpg: encrypted with 4096-bit RSA key, ID <Redacted>, created <Redacted>
      "drmoose <my-email-address>"
gpg: public key decryption failed: Operation cancelled
gpg: decryption failed: No secret key
gpg: secmem usage: 0/32768 bytes in 0 blocks

Why did this ever seem to work? By a "fun" coincidence, my work machine is currently not bootable, so it may be a while before I am able to isolate the difference. Edit: that's fixed and... i get the same behavior as the laptop. So that just makes this even more mysterious. Why did this same computer behave completely differently as recently as this morning?

from passff.

With PASSWORD_STORE_GPG_OPTS='--debug=crypto --status-fd=2' the status messages are interspersed with the log_errors in the stderr output of gpg, but crucially only the log_errors seem to be localized (the others are fixed strings). So, there's an outside possibility (albeit a difficult one) that a post-processor could be written for this interspersed output that uses the [GNUPG:] status markers to decide which stderr lines to include in the "stderr" that gets forwarded to the addon.

This approach would represent an heroic testing effort, since it would have to be robust against every possible combination of gpg version and locale. I could spin up dozens of docker containers... but even considering that option makes this idea feel like an https://xkcd.com/2054/ situation. What's really bothersome is that there would be no good way to seamlessly fail over to the old behavior (unless we're willing to tolerate a much nosier "decryption failed" modal when that happens). But, on the other hand, it would also give us a way to provide error-sensitive help links in the UI for the failure modes people are most commonly on here opening issues about.

I'll pause here for reactions -- I don't want to spend an evening making an "every gpg ever made" container testing harness unless @tuxor1337 feels this is worth pursuing.

from passff.

In principle, it's a nice thing to understand why a particular call to pass failed in order to choose a good way to react. If it's possible to implement this in 100 lines of code, then it's fine. But if it requires that our host script reads and writes files in locations on disk that we previously didn't rely on, and which might cause problems in sandboxed environments (e.g. Firefox running in snap), or if it requires 1000 lines of code to interpret the output, then I guess that it would be a pain to maintain and wouldn't be beneficial to PassFF.

For a similar reason, I decided not to include support for punycode and top-level domain recognition, so far. If there is a slim solution to those problems, I still think that it's totally worth adding more functionality.

from passff.

The specific implementation I had in mind is fairly short with respect to lines of code, and would look something like this sketch:

def cleanStderr(stderr):
    preserve = []
    # https://github.com/gpg/libgpg-error/blob/master/src/err-codes.h.in
    error_code = 0
    for line in stderr.split("\n"):
        if re.match(GPG_STATUS_PAT, line):
            m = re.search(ERROR_CODE_PAT, line)
            if m:
                error_code = int(m.group(1)) & 0xFFFF
            elif NO_SECKEY in line:
                error_code = 17
            elif BEGIN_DECRYPTION in line:
                preserve[:-1] = []
            elif END_DECRYPTION in line:
                break
        elif preserve and line.startswith('  '):
            # gpg indented line continuation
            preserve[-1] += '\n' + line
        else:
            preserve.append(line)
    return '\n'.join(preserve), error_code

The full thing is committed to my fork as 4a50e9ef (+50 lines), and it works on my local machines:

// echo -e '\xFF\xFF\xFF\xFF["temp"]' | ./src/passff.py | tail -c +5 | jq
{
  "exitCode": 2,
  "stdout": "",
  "stderr": "gpg: public key decryption failed: Operation cancelled\ngpg: decryption failed: No secret key",
  "errorCode": 99,
  "version": "_VERSIONHOLDER_"
}
// echo -e '\xFF\xFF\xFF\xFF["temp"]' | ./src/passff.py | tail -c +5 | jq
{
  "exitCode": 2,
  "stdout": "",
  "stderr": "gpg: public key decryption failed: Bad passphrase\ngpg: decryption failed: No secret key",
  "errorCode": 11,
  "version": "_VERSIONHOLDER_"
}
// echo -e '\xFF\xFF\xFF\xFF["temp"]' | ./src/passff.py | tail -c +5 | jq
{
  "exitCode": 0,
  "stdout": "hello world\n",
  "stderr": "gpg: encrypted with 4096-bit RSA key, ID 7433F17069D9F59F, created 2017-11-15\n      \"drmoose <my-email-address>\"\ngpg: AES256 encrypted data\ngpg: original file name=''",
  "errorCode": 0,
  "version": "_VERSIONHOLDER_"
}
// echo -e '\xFF\xFF\xFF\xFF["unreadable"]' | ./src/passff.py | tail -c +5 | jq
{
  "exitCode": 2,
  "stdout": "",
  "stderr": "gpg: encrypted with 3072-bit RSA key, ID <Redacted>, created 2022-11-28\n      \"Some Guy I Know <his-email-address>\"\ngpg: decryption failed: No secret key",
  "errorCode": 17,
  "version": "_VERSIONHOLDER_"
}

If this looks like an acceptable way forward I'll test other gpg versions & locales this evening and file pull requests.

from passff.

Looks good! I would be happy to review your PR.

But do you really need the --debug=crypto flag? On my machine, --status-fd=2 is sufficient and is independent of the --quiet flag.

from passff.

That is the mystery. I didn't really need it as recently as yesterday morning, but I do now, on all my machines. I have entirely failed to figure out why that changed. Given the source code I quoted above, it never should've worked without it. Not being able to make sense of that... nor able to reproduce the "it works without --debug=crypto condition"... is very annoying.

from passff.

I think that, according to the gpg source code, the option --quiet only affects the calls to log_info, but doesn't affect calls to write_status_error. Especially the line with pkdecrypt_failed is not at all affected by --quiet. And I don't see why --debug=crypto would make a difference.

from passff.

The stack trace I posted above shows that the relevant call to write_status_error is this one in print_pkenc_list which is only called if (!opt.quiet).

The opt.quiet gets cleared by opt.debug here

However, this particular case appears to only happen on 2.2.40 of the assorted distros I've tested.

Here's the progress of my testing/algorithm tuning so far. Mercifully on newer gnupgs, things seem to just happily work.

Legend:

• 🇺🇸 Works in Engilsh
• 🇪🇸 Works in Spanish
• 🇯🇵 Works in Japanese
• 🐛 Only works with --debug=crypto
• ⚠️ Substantially different stderr output
• ❌ Detected as something else

from passff.

On some platforms, --debug=crypto outputs a lot of extra gpg: DBG: messages that have to be filtered out, but I picked that one more or less at random just to set the opts.debug flag. --debug=ipc appears to be a better choice. Much less junk in the stderr log and it lets me fill in some of those blanks in the table (which are indistinguishable from each other in the --debug=crypto case)

from passff.

Indeed, the lines with pkdecrypt_failed have been moved from print_pkenc_list to other places that are not affected by --quiet in version 2.4 (and still in the master): https://github.com/gpg/gnupg/blob/master/g10/mainproc.c

Since 2.2, The --quiet option seems to be deactivated altogether if any debug flag is set: https://github.com/gpg/gnupg/blob/STABLE-BRANCH-2-2/g10/gpg.c#L1344-L1345

from passff.

--debug=ipc turns out to be the magic key that unlocks all of the versions on my table except cent 7.

from passff.