From efd9d1626e0d692d287185deb16d295c4636be48 Mon Sep 17 00:00:00 2001 From: Vincent Breitmoser Date: Sat, 13 Sep 2014 21:14:06 +0200 Subject: [PATCH] add a ton of logging to DecryptVerify --- .../keychain/pgp/PgpDecryptVerify.java | 112 ++++++++++++++---- .../results/OperationResultParcel.java | 38 ++++++ .../keychain/ui/DecryptMessageFragment.java | 4 +- OpenKeychain/src/main/res/values/strings.xml | 38 ++++++ 4 files changed, 166 insertions(+), 26 deletions(-) diff --git a/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/pgp/PgpDecryptVerify.java b/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/pgp/PgpDecryptVerify.java index 4e4e8c4e0..769a48a8e 100644 --- a/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/pgp/PgpDecryptVerify.java +++ b/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/pgp/PgpDecryptVerify.java @@ -206,14 +206,14 @@ public class PgpDecryptVerify { // else: ascii armored encryption! go on... } - return decryptVerify(in); + return decryptVerify(in, 0); } catch (PGPException e) { OperationLog log = new OperationLog(); - // log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_PGP_EXCEPTION); + log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_PGP_EXCEPTION, 1); return new DecryptVerifyResult(DecryptVerifyResult.RESULT_ERROR, log); } catch (IOException e) { OperationLog log = new OperationLog(); - // log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_IO); + log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_IO, 1); return new DecryptVerifyResult(DecryptVerifyResult.RESULT_ERROR, log); } } @@ -221,10 +221,13 @@ public class PgpDecryptVerify { /** * Decrypt and/or verifies binary or ascii armored pgp */ - private DecryptVerifyResult decryptVerify(InputStream in) throws IOException, PGPException { + private DecryptVerifyResult decryptVerify(InputStream in, int indent) throws IOException, PGPException { OperationLog log = new OperationLog(); + log.add(LogLevel.START, LogType.MSG_DC, indent); + indent += 1; + PGPObjectFactory pgpF = new PGPObjectFactory(in, new JcaKeyFingerprintCalculator()); PGPEncryptedDataList enc; Object o = pgpF.nextObject(); @@ -239,7 +242,7 @@ public class PgpDecryptVerify { } if (enc == null) { - // log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_INVALID_DATA) + log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_INVALID_SIGLIST, indent); return new DecryptVerifyResult(DecryptVerifyResult.RESULT_ERROR, log); } @@ -252,35 +255,44 @@ public class PgpDecryptVerify { Iterator it = enc.getEncryptedDataObjects(); boolean asymmetricPacketFound = false; boolean symmetricPacketFound = false; + boolean anyPacketFound = false; + // go through all objects and find one we can decrypt while (it.hasNext()) { Object obj = it.next(); if (obj instanceof PGPPublicKeyEncryptedData) { + anyPacketFound = true; + currentProgress += 2; updateProgress(R.string.progress_finding_key, currentProgress, 100); PGPPublicKeyEncryptedData encData = (PGPPublicKeyEncryptedData) obj; - long subKeyId = encData.getKeyID(); + log.add(LogLevel.DEBUG, LogType.MSG_DC_ASYM, indent, + PgpKeyHelper.convertKeyIdToHex(subKeyId)); + CanonicalizedSecretKeyRing secretKeyRing; try { // get actual keyring object based on master key id secretKeyRing = mProviderHelper.getCanonicalizedSecretKeyRing( - KeyRings.buildUnifiedKeyRingsFindBySubkeyUri(encData.getKeyID()) + KeyRings.buildUnifiedKeyRingsFindBySubkeyUri(subKeyId) ); } catch (ProviderHelper.NotFoundException e) { // continue with the next packet in the while loop + log.add(LogLevel.DEBUG, LogType.MSG_DC_ASKIP_NO_KEY, indent +1); continue; } if (secretKeyRing == null) { // continue with the next packet in the while loop + log.add(LogLevel.DEBUG, LogType.MSG_DC_ASKIP_NO_KEY, indent +1); continue; } // get subkey which has been used for this encryption packet secretEncryptionKey = secretKeyRing.getSecretKey(subKeyId); if (secretEncryptionKey == null) { - // continue with the next packet in the while loop + // should actually never happen, so no need to be more specific. + log.add(LogLevel.DEBUG, LogType.MSG_DC_ASKIP_NO_KEY, indent +1); continue; } @@ -294,6 +306,7 @@ public class PgpDecryptVerify { if (!mAllowedKeyIds.contains(masterKeyId)) { // this key is in our db, but NOT allowed! // continue with the next packet in the while loop + log.add(LogLevel.DEBUG, LogType.MSG_DC_ASKIP_NOT_ALLOWED, indent +1); continue; } } @@ -308,14 +321,15 @@ public class PgpDecryptVerify { try { // returns "" if key has no passphrase mPassphrase = mPassphraseCache.getCachedPassphrase(subKeyId); + log.add(LogLevel.DEBUG, LogType.MSG_DC_PASS_CACHED, indent +1); } catch (NoSecretKeyException e) { - // log.add(LogLevel.ERROR, LogType.MSG_DEC_ERROR_NO_KEY); + log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_NO_KEY, indent +1); return new DecryptVerifyResult(DecryptVerifyResult.RESULT_ERROR, log); } - // if passphrase was not cached, return here - // indicating that a passphrase is missing! + // if passphrase was not cached, return here indicating that a passphrase is missing! if (mPassphrase == null) { + log.add(LogLevel.INFO, LogType.MSG_DC_PENDING_PASSPHRASE, indent +1); DecryptVerifyResult result = new DecryptVerifyResult(DecryptVerifyResult.RESULT_PENDING_ASYM_PASSPHRASE, log); result.setKeyIdPassphraseNeeded(subKeyId); @@ -324,9 +338,18 @@ public class PgpDecryptVerify { } // break out of while, only decrypt the first packet where we have a key - // TODO???: There could be more pgp objects, which are not decrypted! break; - } else if (mAllowSymmetricDecryption && obj instanceof PGPPBEEncryptedData) { + + } else if (obj instanceof PGPPBEEncryptedData) { + anyPacketFound = true; + + log.add(LogLevel.DEBUG, LogType.MSG_DC_SYM, indent); + + if (! mAllowSymmetricDecryption) { + log.add(LogLevel.WARN, LogType.MSG_DC_SYM_SKIP, indent +1); + continue; + } + /* * When mAllowSymmetricDecryption == true and we find a data packet here, * we do not search for other available asymmetric packets! @@ -338,15 +361,30 @@ public class PgpDecryptVerify { // if no passphrase is given, return here // indicating that a passphrase is missing! if (mPassphrase == null) { + log.add(LogLevel.INFO, LogType.MSG_DC_PENDING_PASSPHRASE, indent +1); return new DecryptVerifyResult(DecryptVerifyResult.RESULT_PENDING_SYM_PASSPHRASE, log); } // break out of while, only decrypt the first packet - // TODO???: There could be more pgp objects, which are not decrypted! break; } } + // More data, just acknowledge and ignore. + while (it.hasNext()) { + Object obj = it.next(); + if (obj instanceof PGPPublicKeyEncryptedData) { + log.add(LogLevel.WARN, LogType.MSG_DC_TRAIL_ASYM, 0); + } else if (obj instanceof PGPPBEEncryptedData) { + log.add(LogLevel.WARN, LogType.MSG_DC_TRAIL_SYM, 0); + } else { + log.add(LogLevel.WARN, LogType.MSG_DC_TRAIL_UNKNOWN, 0); + } + } + + log.add(LogLevel.DEBUG, LogType.MSG_DC_PREP_STREAMS, indent); + + // we made sure above one of these two would be true if (symmetricPacketFound) { currentProgress += 2; updateProgress(R.string.progress_preparing_streams, currentProgress, 100); @@ -358,18 +396,20 @@ public class PgpDecryptVerify { mPassphrase.toCharArray()); clear = encryptedDataSymmetric.getDataStream(decryptorFactory); - encryptedData = encryptedDataSymmetric; + } else if (asymmetricPacketFound) { currentProgress += 2; updateProgress(R.string.progress_extracting_key, currentProgress, 100); + try { + log.add(LogLevel.WARN, LogType.MSG_DC_UNLOCKING, indent +1); if (!secretEncryptionKey.unlock(mPassphrase)) { - // log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_BAD_PASSPHRASE); + log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_BAD_PASSPHRASE, indent +1); return new DecryptVerifyResult(DecryptVerifyResult.RESULT_ERROR, log); } } catch (PgpGeneralException e) { - // log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_EXTRACT_KEY); + log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_EXTRACT_KEY, indent +1); return new DecryptVerifyResult(DecryptVerifyResult.RESULT_ERROR, log); } @@ -381,8 +421,7 @@ public class PgpDecryptVerify { = secretEncryptionKey.getDecryptorFactory(mDecryptedSessionKey); clear = encryptedDataAsymmetric.getDataStream(decryptorFactory); } catch (NfcSyncPublicKeyDataDecryptorFactoryBuilder.NfcInteractionNeeded e) { - // log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_NFC_INTERACTION); - + log.add(LogLevel.INFO, LogType.MSG_DC_PENDING_NFC, indent +1); DecryptVerifyResult result = new DecryptVerifyResult(DecryptVerifyResult.RESULT_PENDING_NFC, log); result.setNfcEncryptedSessionKey(e.encryptedSessionKey); @@ -391,8 +430,10 @@ public class PgpDecryptVerify { } encryptedData = encryptedDataAsymmetric; } else { + // If we didn't find any useful data, error out // no packet has been found where we have the corresponding secret key in our db - // log.add(LogLevel.ERROR, LogType.MSG_DC_MISSING_SECRET_KEY); + log.add(LogLevel.ERROR, + anyPacketFound ? LogType.MSG_DC_ERROR_NO_KEY : LogType.MSG_DC_ERROR_NO_DATA, indent +1); return new DecryptVerifyResult(DecryptVerifyResult.RESULT_ERROR, log); } @@ -403,7 +444,11 @@ public class PgpDecryptVerify { CanonicalizedPublicKeyRing signingRing = null; CanonicalizedPublicKey signingKey = null; + log.add(LogLevel.DEBUG, LogType.MSG_DC_CLEAR, indent); + indent += 1; + if (dataChunk instanceof PGPCompressedData) { + log.add(LogLevel.DEBUG, LogType.MSG_DC_CLEAR_DECOMPRESS, indent +1); currentProgress += 2; updateProgress(R.string.progress_decompressing_data, currentProgress, 100); @@ -416,6 +461,7 @@ public class PgpDecryptVerify { PGPOnePassSignature signature = null; if (dataChunk instanceof PGPOnePassSignatureList) { + log.add(LogLevel.DEBUG, LogType.MSG_DC_CLEAR_SIGNATURE, indent +1); currentProgress += 2; updateProgress(R.string.progress_processing_signature, currentProgress, 100); @@ -466,6 +512,8 @@ public class PgpDecryptVerify { OpenPgpMetadata metadata; if (dataChunk instanceof PGPLiteralData) { + log.add(LogLevel.DEBUG, LogType.MSG_DC_CLEAR_DATA, indent +1); + indent += 2; currentProgress += 4; updateProgress(R.string.progress_decrypting, currentProgress, 100); @@ -506,8 +554,14 @@ public class PgpDecryptVerify { literalData.getModificationTime().getTime(), originalSize); + log.add(LogLevel.DEBUG, LogType.MSG_DC_CLEAR_META_FILE, indent +1); + log.add(LogLevel.DEBUG, LogType.MSG_DC_CLEAR_META_MIME, indent +1); + log.add(LogLevel.DEBUG, LogType.MSG_DC_CLEAR_META_TIME, indent +1); + log.add(LogLevel.DEBUG, LogType.MSG_DC_CLEAR_META_SIZE, indent +1); + // return here if we want to decrypt the metadata only if (mDecryptMetadataOnly) { + log.add(LogLevel.OK, LogType.MSG_DC_OK_META_ONLY, indent); DecryptVerifyResult result = new DecryptVerifyResult(DecryptVerifyResult.RESULT_OK, log); result.setDecryptMetadata(metadata); @@ -554,6 +608,7 @@ public class PgpDecryptVerify { if (signature != null) { updateProgress(R.string.progress_verifying_signature, 90, 100); + log.add(LogLevel.DEBUG, LogType.MSG_DC_CLEAR_SIGNATURE_CHECK, indent); PGPSignatureList signatureList = (PGPSignatureList) plainFact.nextObject(); PGPSignature messageSignature = signatureList.get(signatureIndex); @@ -564,8 +619,15 @@ public class PgpDecryptVerify { // Verify signature and check binding signatures boolean validSignature = signature.verify(messageSignature); + if (validSignature) { + log.add(LogLevel.DEBUG, LogType.MSG_DC_CLEAR_SIGNATURE_OK, indent +1); + } else { + log.add(LogLevel.WARN, LogType.MSG_DC_CLEAR_SIGNATURE_BAD, indent +1); + } signatureResultBuilder.setValidSignature(validSignature); } + + indent -= 1; } else { // If there is no literalData, we don't have any metadata metadata = null; @@ -575,9 +637,9 @@ public class PgpDecryptVerify { updateProgress(R.string.progress_verifying_integrity, 95, 100); if (encryptedData.verify()) { - // log.add(LogLevel.INFO, LogType.MSG_DC_INTEGRITY_CHECK_OK) + log.add(LogLevel.INFO, LogType.MSG_DC_INTEGRITY_CHECK_OK, indent); } else { - // log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_INTEGRITY_CHECK) + log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_INTEGRITY_CHECK, indent); return new DecryptVerifyResult(DecryptVerifyResult.RESULT_ERROR, log); } } else { @@ -588,13 +650,15 @@ public class PgpDecryptVerify { // Handle missing integrity protection like failed integrity protection! // The MDC packet can be stripped by an attacker! if (!signatureResultBuilder.isValidSignature()) { - // log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_INTEGRITY_CHECK) + log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_INTEGRITY_CHECK, indent); return new DecryptVerifyResult(DecryptVerifyResult.RESULT_ERROR, log); } } updateProgress(R.string.progress_done, 100, 100); + log.add(LogLevel.OK, LogType.MSG_DC_OK, indent); + // Return a positive result, with metadata and verification info DecryptVerifyResult result = new DecryptVerifyResult(DecryptVerifyResult.RESULT_OK, log); @@ -649,7 +713,7 @@ public class PgpDecryptVerify { PGPSignatureList sigList = (PGPSignatureList) pgpFact.nextObject(); if (sigList == null) { - // log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_INVALID_DATA) + log.add(LogLevel.ERROR, LogType.MSG_DC_ERROR_INVALID_SIGLIST, 0); return new DecryptVerifyResult(DecryptVerifyResult.RESULT_ERROR, log); } diff --git a/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/service/results/OperationResultParcel.java b/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/service/results/OperationResultParcel.java index 580072957..1a77d96d3 100644 --- a/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/service/results/OperationResultParcel.java +++ b/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/service/results/OperationResultParcel.java @@ -435,6 +435,44 @@ public class OperationResultParcel implements Parcelable { MSG_EK_ERROR_DUMMY (R.string.msg_ek_error_dummy), MSG_EK_ERROR_NOT_FOUND (R.string.msg_ek_error_not_found), + // decryptverify + MSG_DC_ASKIP_NO_KEY (R.string.msg_dc_askip_no_key), + MSG_DC_ASKIP_NOT_ALLOWED (R.string.msg_dc_askip_not_allowed), + MSG_DC_ASYM (R.string.msg_dc_asym), + MSG_DC_CLEAR_DATA (R.string.msg_dc_clear_data), + MSG_DC_CLEAR_DECOMPRESS (R.string.msg_dc_clear_decompress), + MSG_DC_CLEAR_META_FILE (R.string.msg_dc_clear_meta_file), + MSG_DC_CLEAR_META_MIME (R.string.msg_dc_clear_meta_mime), + MSG_DC_CLEAR_META_SIZE (R.string.msg_dc_clear_meta_size), + MSG_DC_CLEAR_META_TIME (R.string.msg_dc_clear_meta_time), + MSG_DC_CLEAR (R.string.msg_dc_clear), + MSG_DC_CLEAR_SIGNATURE_BAD (R.string.msg_dc_clear_signature_bad), + MSG_DC_CLEAR_SIGNATURE_CHECK (R.string.msg_dc_clear_signature_check), + MSG_DC_CLEAR_SIGNATURE_OK (R.string.msg_dc_clear_signature_ok), + MSG_DC_CLEAR_SIGNATURE (R.string.msg_dc_clear_signature), + MSG_DC_ERROR_BAD_PASSPHRASE (R.string.msg_dc_error_bad_passphrase), + MSG_DC_ERROR_EXTRACT_KEY (R.string.msg_dc_error_extract_key), + MSG_DC_ERROR_INTEGRITY_CHECK (R.string.msg_dc_error_integrity_check), + MSG_DC_ERROR_INVALID_SIGLIST(R.string.msg_dc_error_invalid_siglist), + MSG_DC_ERROR_IO (R.string.msg_dc_error_io), + MSG_DC_ERROR_NO_DATA (R.string.msg_dc_error_no_data), + MSG_DC_ERROR_NO_KEY (R.string.msg_dc_error_no_key), + MSG_DC_ERROR_PGP_EXCEPTION (R.string.msg_dc_error_pgp_exception), + MSG_DC_INTEGRITY_CHECK_OK (R.string.msg_dc_integrity_check_ok), + MSG_DC_OK_META_ONLY (R.string.msg_dc_ok_meta_only), + MSG_DC_OK (R.string.msg_dc_ok), + MSG_DC_PASS_CACHED (R.string.msg_dc_pass_cached), + MSG_DC_PENDING_NFC (R.string.msg_dc_pending_nfc), + MSG_DC_PENDING_PASSPHRASE (R.string.msg_dc_pending_passphrase), + MSG_DC_PREP_STREAMS (R.string.msg_dc_prep_streams), + MSG_DC (R.string.msg_dc), + MSG_DC_SYM (R.string.msg_dc_sym), + MSG_DC_SYM_SKIP (R.string.msg_dc_sym_skip), + MSG_DC_TRAIL_ASYM (R.string.msg_dc_trail_asym), + MSG_DC_TRAIL_SYM (R.string.msg_dc_trail_sym), + MSG_DC_TRAIL_UNKNOWN (R.string.msg_dc_trail_unknown), + MSG_DC_UNLOCKING (R.string.msg_dc_unlocking), + ; private final int mMsgId; diff --git a/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/ui/DecryptMessageFragment.java b/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/ui/DecryptMessageFragment.java index 75e38d5c6..a7a630be1 100644 --- a/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/ui/DecryptMessageFragment.java +++ b/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/ui/DecryptMessageFragment.java @@ -156,7 +156,7 @@ public class DecryptMessageFragment extends DecryptFragment { return; } // error, we can't work with this! - result.createNotify(getActivity()); + result.createNotify(getActivity()).show(); return; } @@ -165,7 +165,7 @@ public class DecryptMessageFragment extends DecryptFragment { mMessage.setText(new String(decryptedMessage)); mMessage.setHorizontallyScrolling(false); - result.createNotify(getActivity()); + result.createNotify(getActivity()).show(); // display signature result in activity onResult(result); diff --git a/OpenKeychain/src/main/res/values/strings.xml b/OpenKeychain/src/main/res/values/strings.xml index a450b36f8..4e23f36b0 100644 --- a/OpenKeychain/src/main/res/values/strings.xml +++ b/OpenKeychain/src/main/res/values/strings.xml @@ -764,6 +764,44 @@ "Cannot edit keyring with stripped master key!" "Key not found!" + + "Data not encrypted with known key, skipping…" + "Data not encrypted with allowed key, skipping…" + "Found block of asymmetrically encrypted data" + "Processing literal data" + "Unpacking compressed data" + "Filesize: %s" + "MIME type: %s" + "Filesize: %s" + "Modification time: %s" + "Signature check NOT OK!" + "Verifying signature data" + "Signature check OK" + "Saving signature data for later" + "Processing cleartext data" + "Error unlocking key, bad passphrase!" + "Unknown error unlocking key!" + "Integrity check error!" + "No valid signature data found!" + "Encountered IO Exception during operation!" + "No encrypted data found in stream!" + "No encrypted data with known secret key found in stream!" + "Encountered PGP Exception during operation!" + "Integrity check ok!" + "Only metadata was requested, skipping decryption" + "OK" + "Using passphrase from cache" + "NFC token required, requesting user input…" + "Passphrase required, requesting user input…" + "Preparing streams for decryption" + "Starting decrypt operation…" + "Symmetric data not allowed, skipping…" + "Found block of symmetrically encrypted data" + "Encountered trailing, asymmetrically encrypted data" + "Encountered trailing, symmetrically encrypted data" + "Encountered trailing data of unknown type" + "Unlocking secret key" + "Click to clear cached passphrases" "OpenKeychain has cached %d passphrases"