User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Firefox/78.0

Steps to reproduce:

Opened any encrypted message, either old (which were likely sent using Enigmail, and displayed correctly under Thunderbird+Enigmail) or brand new (i.e. sent to myself using this Thunderbird version).

I’m using the external GnuPG feature. I’m apparently able to sign correctly, so it’s likely not an issue with the setup.

Actual results:

Message cannot be decrypted.

In the console log, I can see this:
rnp_op_verify_execute returned unexpected: 268435457

Expected results:

Message should be decrypted and displayed successfully.

Hello Bruno, thank you for reporting. Please update the summary to reflect that it concerns the external GnuPG feature, for example:

Decrypt with external GnuPG fails with rnp_op_verify_execute returned unexpected

Hi Ben,

Done. Is there anything else I can do to help debug this?

For debugging it, see https://wiki.mozilla.org/Thunderbird:OpenPGP#Debugging_.2F_Tracing

Code 268435457 is RNP_ERROR_BAD_FORMAT

We always start by trying to decrypt with the internal RNP.
Apparently RNP think thiss isn't just a missing secret key, it thinks the whole PGP message is bad.

For a message that you send to yourself, do you get the same problem with the copy of the message that is stored in your Sent folder?

Looking at our code, I see that for the above error code, we currently don't attempt to decrypt using GPGME. (We only do that for error codes RNP_ERROR_DECRYPT_FAILED and RNP_ERROR_NO_SUITABLE_KEY.)

It would help us to get a copy of a message in that broken format.

Could you please follow the instruction from bug 1663400 comment 2 to send a test message?
After you sent the test message, please confirm that the copy in your sent folder gives you the same problem.
We'll then try to investigate what's happening.
Thanks in advance.

So, I’ve sent an email to Kai following the instructions. I confirm I can neither debug the copy stored in Sent, nor the copy sent to my myself.

In the system console, I get this more detailed output using RNP_LOG_CONSOLE=1:

[init_encrypted_src() /build/thunderbird/src/thunderbird-78.4.0/comm/third_party/rnp/src/librepgp/stream-parse.cpp:2044] failed to obtain decrypting key or password
[init_packet_sequence() /build/thunderbird/src/thunderbird-78.4.0/comm/third_party/rnp/src/librepgp/stream-parse.cpp:2268] wrong pkt tag 45
console.debug: "rnp_op_verify_execute returned unexpected: 268435457"

The enigdbug.txt file seems uninteresting w.r.t. the console log, in fact they are identical except for those three lines that are only in the console output.

I’ve also attached to this bug the message as stored in my Sent folder.

Thanks for the test message.
I can decrypt it just fine.

(In reply to Bruno Pagani from comment #5)

[init_encrypted_src() /build/thunderbird/src/thunderbird-78.4.0/comm/third_party/rnp/src/librepgp/stream-parse.cpp:2044] failed to obtain decrypting key or password
[init_packet_sequence() /build/thunderbird/src/thunderbird-78.4.0/comm/third_party/rnp/src/librepgp/stream-parse.cpp:2268] wrong pkt tag 45
console.debug: "rnp_op_verify_execute returned unexpected: 268435457"

This is probably the cause of your problem.

The missing decrypting key is expected, because as you said, you're using the external key in gnupg configuration.

So for some reason, RNP is unhappy with this message in general, and thinks it contains a problem, and is therefore complaining about it.

Nickolay, do you want to check what's happening here?
I'll forward you an email that was encrypted to the key material that can be found on gitlab here:
https://gitlab.com/openpgp-wg/openpgp-samples

Independent of the detail with RNP, we should probably extend the list of error scenarios, in which Thunderbird should continue to attempt decrpyting with GPGME.

The attached patch adds the fallback for additional error codes, I've added the ones that seemed reasonable to me, which are those that don't suggest a general fatal failure (e.g. other than a failure to understand the data).

Pushed by kaie@kuix.de:
https://hg.mozilla.org/comm-central/rev/bfa8183cf7b8
Allow fallback to GPGME decryption in additional RNP failure scenarios. r=PatrickBrunschwig

I assume there'll be no additional 83.x beta.
This is a very obvious correctness fix, I think it's safe to put it into esr78 without waiting.

Comment on attachment 9187153 [details]
Bug 1675939 - Allow fallback to GPGME decryption in additional RNP failure scenarios. r=PatrickBrunschwig

[Approval Request Comment]
Regression caused by (bug #):
User impact if declined: users cannot decrypt certain messages, limited to users of non-default external gnupg configuration
Testing completed (on c-c, etc.):
Risk to taking this patch (and alternatives if risky): low

I’ve tried your patch above 78.4.1 sources, but it still does not work:

[DEBUG] mimeDecryp.jsm: starting decryption
[DEBUG] mimeDecrypt.jsm: got API: RNP
[DEBUG] rnp-cryptoAPI.js: decryptMime()
[DEBUG] rnp-cryptoAPI.js: decrypt()
[init_encrypted_src() /build/thunderbird/src/thunderbird-78.4.1/comm/third_party/rnp/src/librepgp/stream-parse.cpp:2044] failed to obtain decrypting key or password
[init_packet_sequence() /build/thunderbird/src/thunderbird-78.4.1/comm/third_party/rnp/src/librepgp/stream-parse.cpp:2268] wrong pkt tag 45
[DEBUG] mimeDecrypt.jsm: done: 268435457
[DEBUG] mimeDecrypt.jsm: displayStatus()

The only visible change is that the line console.debug: "rnp_op_verify_execute returned unexpected: 268435457" disappeared, but it seems to be still treated as some sort of return value from the decryption.

Comment on attachment 9187153 [details]
Bug 1675939 - Allow fallback to GPGME decryption in additional RNP failure scenarios. r=PatrickBrunschwig

thanks for the quick feedback, removing the request for branch approval

Bruno, it's expected that you still get the error output on the console. We cannot prevent that.

However, afterwards, with the new code, we should try to run a decrypt through GnuPG.

Do you possibly have a chance to enable GPGME logging, and see if we access it to attempt the decryption?

Alternatively, it sounds like you are building Thunderbird locally?
If that's true, then I could create a patch that enables more logging, so we see what our code attempts to do.

(In reply to Kai Engert (:KaiE:) from comment #17)

Bruno, it's expected that you still get the error output on the console. We cannot prevent that.

However, afterwards, with the new code, we should try to run a decrypt through GnuPG.

Do you possibly have a chance to enable GPGME logging, and see if we access it to attempt the decryption?

I don’t know how to do that, but if you have a link with instructions I can try to follow them.

Alternatively, it sounds like you are building Thunderbird locally?
If that's true, then I could create a patch that enables more logging, so we see what our code attempts to do.

Yes I am (I’m an Arch Linux packager, testing our new build for issues before we release it). I could definitively use such a patch.

(In reply to Bruno Pagani from comment #18)

(In reply to Kai Engert (:KaiE:) from comment #17)

Bruno, it's expected that you still get the error output on the console. We cannot prevent that.

However, afterwards, with the new code, we should try to run a decrypt through GnuPG.

Do you possibly have a chance to enable GPGME logging, and see if we access it to attempt the decryption?

I don’t know how to do that, but if you have a link with instructions I can try to follow them.

OK, it was quite simple actually: https://www.gnupg.org/documentation/manuals/gpgme/Debugging.html

I see thousands of line in this file as soon as I try to open the encrypted email in TB.

Sorry for a bit late reply. I re-checked with the latest CLI utility - and rnp_op_verify_execute() returns correct RNP_ERROR_NO_SUITABLE_KEY on that message, so looks like it's the problem of the different workflow/functions call order.

Kai, do you make use of rnp_ffi_set_key_provider() ? Within it you may distinguish which keys are required to decrypt the data, and do a fallback to the GnuPG if the corresponding secret key is not available.

I can confirm Nickolay's observation, I'm actually getting RNP_ERROR_NO_SUITABLE_KEY, too, with the RNP snapshot from September 13, the one we still include in the stable release.

Bruno, the behavior you're observing is different from the one we see with our builds.

I wonder if there is anything special about your Thunderbird build for Arch Linux that has the side effect of causing the problem you see.

Which RNP and Botan libraries are you using? Are you using the ones that are contained in the Thunderbird source distribution, or are you using other versions?

Your log output from above

[init_packet_sequence() /build/thunderbird/src/thunderbird-78.4.1/comm/third_party/rnp/src/librepgp/stream-parse.cpp:2268] wrong pkt tag 45

seems to clarify that you're using the RNP code that Thunderbird includes.

However, I don't get this message when opening the test message you had sent to me - when using a configuration in which RNP doesn't have access to required secret key material, as in your scenario.

We are using system botan, so 2.17.1. You can see for which library we are using system ones (as much as possible in fact) here: https://git.archlinux.org/svntogit/packages.git/tree/trunk/mozconfig.cfg?h=packages/thunderbird

I’ll try with vendored botan version and see if that is the culprit.

Same issue using vendored botan (I realized that I did not state explicitly it since you found it by yourself, but yes we use Thunderbird vendored RNP since we don’t package it currently —this might change in the future).

Not sure what I should do at this point?

Do you have at least one secret key imported to the Thunderbird (or generated there), or do not have them at all? Maybe that could make a difference.

No, they are no any secret key in Thunderbird. I’ve just generated one for some identity to try, but that did not make any change.

OK, so I went a step further and tried the official Mozilla binaries. And I get the same issue:

[init_encrypted_src() /builds/worker/checkouts/gecko/comm/third_party/rnp/src/librepgp/stream-parse.cpp:2044] failed to obtain decrypting key or password
[init_packet_sequence() /builds/worker/checkouts/gecko/comm/third_party/rnp/src/librepgp/stream-parse.cpp:2268] wrong pkt tag 45

I’ve also tried in a clean profile, after setting up a dummy account and adding the message to it, as well as setting GnuPG and the key in E2E settings, to no avail (exactly the same error as above, while the gpgme.log file gets filled with content).

So to summarize:

• for the same message, you get error BAD_FORMAT, but both Nickolay and I get error NO_SUITABLE_KEY
• we don't understand why you get error BAD_FORMAT
• you've tested code that attempts decryption with GPGME for error error BAD_FORMAT
• your testing and logging seems to confirm that the experimental patch indeed enabled fallback to GPGME
• if you don't see a decrypted message, it means that GnuPG cannot decrypt your message, or that your message is corrupted.

If RNP reports BAD_FORMAT, and GPGME cannot decrypt, it seems most likely that you are experiencing some kind of data corruption.

Bruno, at this time I have no idea what could go wrong.
I suggest that as the next step you investigate if the message files that Thunderbird accesses might be corrupted.

I think the easiest is to work with the example message that you had sent.

I will edit the message you had sent to alice-test remove the headers, and attach it.
Hopefully you still have the message in your sent folder. Use file save as to save the message from inside Thunderbird to a .eml file. Then compare your saved file with the file I will attach. Do you see any corruption or difference in the file you have saved?

Then try to use GnuPG to decrypt both your file and my file. Can GnuPG decrypt both, or is there a failure?

Never mind. You had already attached your copy from the sent folder.

Are you able to decrypt that file with gnupg?

Yeah, it’s definitively not a corruption issue, as even loading the message attached here into a clean profile lead to the same issue.

I’ve attached the output of gpg --decrypt message.eml, so you can see that definitively works.

If you want to provide patches around that code path to get more debug, I’ll happily test them and report.

Bruno, here is a patch that adds logging. It's based on current comm-esr78, which should be almost identical to the soon-to-be-released 78.5.0

I've prepared my environment this way:

• saved file message.eml that you had attached to this bug
• used a Thunderbird profile that does NOT have the Alice/Bob secret keys
• set pref allow_external_gnupg to true
• imported Alice's secret key into the GnuPG keyring (no smartcard)
• started Thunderbird.
• opened error console
• cleared error console (trash button)
• in the TB main window, "file open saved message", selected your file
• back to error console
• right click, export visible messages to file

I'm attaching the file that produced.

We can see the following in the file:

• rnp_op_verify_execute exitCode: 301989894 (no suitable key)
• calling GPGME.decrypt
• GPGMELib.gpgme_op_decrypt_ext exitCode: 0
• r2.decryptedData contains a PGP block with different contents.
  That's the result of GPGME having stripped away the encryption, and having produced a new block that only contains the remaining signature information
• recursive call to RNP.decrypt
  That call will process the remaining encoding and evaluate the signature
• rnp_op_verify_execute exitCode: 0
  RNP reports the processing of that inner data was good
• result.decryptedData: shows the message that you have attached as "decrypted.txt"

Can you please do the same, and provide the file you get from saving the error console?

Comment on attachment 9188300 [details]
Bug 1675939 - Add pref to automatically accept OpenPGP public key as accepted/unverified on import. r=PatrickBrunschwig

Revision D97316 was moved to bug 1675342. Setting attachment 9188300 [details] to obsolete.

Please ignore the previous comment, it was intended for a different bug.

So here you go. This is trying to decrypt with my key, I’ll try again with Alice’s.

That's interesting. On your system, GPGME reports a successful operation.
"GPGMELib.gpgme_op_decrypt_ext exitCode: 0"

But the decrypted data it returns looks differently.

Could you please provide the full message block? The second pink section, the one that starts with "LS0tLS1CRUdJTiBQR1AgTU...".

By default, the message is truncated. There's a little arrow in front of it, if you click it, it will expand. Then you can right click and copy it. Could you please save it to a file and attach?

From the first section, because of the identical line "sha1: 86bd2366b2e4c8ff80f1a950f7c3ffdaf311ee6a RNP.jsm:923:9" in both of our logs, we know that on your system, it operates on the same input that I got.

(In reply to Kai Engert (:KaiE:) from comment #39)

That's interesting. On your system, GPGME reports a successful operation.
"GPGMELib.gpgme_op_decrypt_ext exitCode: 0"

But the decrypted data it returns looks differently.

Could you please provide the full message block? The second pink section, the one that starts with "LS0tLS1CRUdJTiBQR1AgTU...".

By default, the message is truncated. There's a little arrow in front of it, if you click it, it will expand. Then you can right click and copy it. Could you please save it to a file and attach?

Actually I had exported it like this for the first time, then while comparing to yours I realized I could keep the section collapsed. ^^ So here is the previous log with expanded sections.

BTW, the log for Alice’s key is bit for bit identical (the only difference is that I don’t get asked for my passphrase by the gpg-agent, which is expected since Alice’s is not passphrase protected).

Thanks. What are the versions of GnuPG and GPGME that you have installed?

Respectively 2.2.23 and 1.14.0. I can try 2.2.24 and 1.15.0 (quite easily for the second one as it is already available in the [testing] repository).

Same issue on GPGME 1.15.0.

I think I understand what's happening.

We're calling gpgme_op_decrypt_ext with flag GPGME_DECRYPT_UNWRAP - which is equivalent to the (almost undocumented) functionality from "gpg --unwrap"

In all my past experiments, the output of that code was always a binary PGP message. Because I cannot easily process that binary output, I'm always using code to transform that into "armored" PGP content.

If I run a base64 decoding operating on the block you got, it looks like the output that I get.

So apparently, on your system, the result of "gpg --unwrap" isn't binary, but it's already armored. We apply another level of armoring, and RNP fails to decode it.

On my system I'm using gpg 2.2.20 and GPGME 1.12.0. Your versions are newer.

I see I have a call to gpgme_set_armor(1). I remember that had not given me the expected results, which was the reason why I had added applied an RNP function for armoring on top of the GPGME output.

I'm guessing that newer versions of GPGME have fixed this to work correctly.

I suggest we remove the call to gpgme_set_armor, and always rely on the RNP armoring code, so it can work consistently with old and new gpg versions.

I'll make a patch for you to try.

I’m compiling with your patch, but not sure that will work: I do have armor in my gpg.conf file. This has been a recommended setting for ages (so long that I do not even remember why exactly), and it might be responsible for armoring the output of your gpg --unwrap call. If I’m right, it means the output will still be armored even after patching out that line.

I’ll make a quick test by removing this line from my configuration and see if that changes something while the compilation runs.

Bingo, removing armor from my config make it work. So I’m quite sure your patch won’t work.

I'm glad you confirmed it's the armoring.

I wasn't aware that a config in gpg.conf can override the default. It sounds like it's better if we dynamically check if the data we've received from GPGME is armored or not, and only apply the armoring using RNP if we're using a buggy version.

Comment on attachment 9188378 [details] [diff] [review]
no-gpgme-unwrap-armor.patch

This patch cannot work. The change is in the signing code, I hadn't paid attention.

This patch v3 works for me in the following scenarios:

• default gpg.conf (no "armor" statement) and old GPG
  (I used logging to confirm we detect the missing armoring and call RNP enarmor)
• gpg.conf containing "armor"
  (I used logging to confirm we detect the armored data)

In both scenarios, the message is correctly displayed.

Bruno, would you like to test this patch with your newer gpg versions?
Thanks in advance

Yes, it works for me! Congratulations on finding the root cause and fixing it properly. :)

Thank you for patiently working with us!

Pushed by kaie@kuix.de:
https://hg.mozilla.org/comm-central/rev/3396fcaf2cdc
Detect if output from GPGME.gpgme_op_decrypt_ext is armored. r=PatrickBrunschwig

Comment on attachment 9187153 [details]
Bug 1675939 - Allow fallback to GPGME decryption in additional RNP failure scenarios. r=PatrickBrunschwig

[Approval Request Comment]
Regression caused by (bug #): no
User impact if declined: smartcard users cannot use latest GnuPG versions
Testing completed (on c-c, etc.): manually
Risk to taking this patch (and alternatives if risky): low, impact limited to users of non-default config

Comment on attachment 9188424 [details]
Bug 1675939 - Detect if output from GPGME.gpgme_op_decrypt_ext is armored. r=PatrickBrunschwig

[Approval Request Comment]
Regression caused by (bug #): no
User impact if declined: smartcard users cannot use latest GnuPG versions
Testing completed (on c-c, etc.): manually
Risk to taking this patch (and alternatives if risky): low, impact limited to users of non-default config

Comment on attachment 9188424 [details]
Bug 1675939 - Detect if output from GPGME.gpgme_op_decrypt_ext is armored. r=PatrickBrunschwig

[Triage Comment]
Approved for beta

Comment on attachment 9187153 [details]
Bug 1675939 - Allow fallback to GPGME decryption in additional RNP failure scenarios. r=PatrickBrunschwig

[Triage Comment]
Approved for beta

Comment on attachment 9187153 [details]
Bug 1675939 - Allow fallback to GPGME decryption in additional RNP failure scenarios. r=PatrickBrunschwig

oh, this first part is already on the 84 branch.

https://hg.mozilla.org/releases/comm-beta/rev/55af5323f130fd63c810c670fdcf5871b1471da2
84.0b2

Comment on attachment 9188424 [details]
Bug 1675939 - Detect if output from GPGME.gpgme_op_decrypt_ext is armored. r=PatrickBrunschwig

[Approval Request Comment]
Regression caused by (bug #): no
User impact if declined: smartcard users cannot use latest GnuPG versions
Testing completed (on c-c, etc.): manually
Risk to taking this patch (and alternatives if risky): low, impact limited to users of non-default config

Comment on attachment 9187153 [details]
Bug 1675939 - Allow fallback to GPGME decryption in additional RNP failure scenarios. r=PatrickBrunschwig

[Approval Request Comment]
Regression caused by (bug #): no
User impact if declined: smartcard users cannot use latest GnuPG versions
Testing completed (on c-c, etc.): manually
Risk to taking this patch (and alternatives if risky): low, impact limited to users of non-default config

Comment on attachment 9188424 [details]
Bug 1675939 - Detect if output from GPGME.gpgme_op_decrypt_ext is armored. r=PatrickBrunschwig

[Triage Comment]
Approved for esr78

Comment on attachment 9187153 [details]
Bug 1675939 - Allow fallback to GPGME decryption in additional RNP failure scenarios. r=PatrickBrunschwig

[Triage Comment]
Approved for esr78

78.5.1
https://hg.mozilla.org/releases/comm-esr78/rev/abc73496b083e6c4842d5bdc76ed6f60eea53aa4
https://hg.mozilla.org/releases/comm-esr78/rev/d3e2e71dde622e10eb7c79c21461aa690fca71a2

(In reply to Pulsebot from comment #13)

Pushed by kaie@kuix.de:
https://hg.mozilla.org/comm-central/rev/4ace0f66e67d
Fix forgotton colon, reported by eslint. rs=bustage DONTBUILD

forgotton in initial esr78 uplift... sorry

got a=wsmwk in chat.

https://hg.mozilla.org/releases/comm-esr78/rev/a14eafb64ef5d1dedcca24530cab174816e9dbed

Bruno, I consider to backout (undo) the first of the two patches.

I believe it is unnecessary to fix your scenario.
And I discovered that it can cause false message feedback to be given - if the signature processing of a message results in a failure, our UI can incorrectly report that it's a decrypted message that we cannot decrypt.

Would you like to test that undoing

https://hg.mozilla.org/comm-central/rev/bfa8183cf7b8
https://hg.mozilla.org/comm-central/rev/4ace0f66e67d

still works as expected?

@Kai: Yeah, I think you’re right. I cannot test right now, but I’m pretty sure that won’t be an issue. I’ll re-open after 78.5.1 (since the revert has been targeted for this release) if it ever happens to break.

This already did work in TB 84.0b2, but it's broken again in both, TB 84.0b3, and Daily 85.0a1 (2020-12-04).
Reopening.

Also, can anyone confirm whether bug 1660041 is the exact same problem?

@Christian 1660041 is of different source: extra chars in the armored message, which should be stripped out by the Thunderbird (see https://bugzilla.mozilla.org/show_bug.cgi?id=1660041#c17)

The reason I'm asking is because the message from the Error Console is exactly the same for both bugs:
rnp_op_verify_execute returned unexpected: 268435457

And the initial fix for this bug did also work for the problematic messages mentioned in bug 1660041, at least temporarily with TB 84.0b2. But not anymore now with 84.0b3.

I think we should keep this bug fixed. The cause of the other problem is different from the issue described in this bug.

It is important feedback that the initial commit in this bug helped for the symptom in bug 1660041.
I have an idea what happened, but I think further discussion on this should be done in bug 1660041, I'll comment there.