debug-logging.diff

# HG changeset patch
# User Dana Keeler <dkeeler@mozilla.com>
# Date 1545342385 28800
#      Thu Dec 20 13:46:25 2018 -0800
# Node ID 3a62d515901fd328421178bb55998001e3d95294
# Parent  1e46bd8dc997145cc29c7e8465d1648eab52c84e
debug logging

diff --git a/security/manager/ssl/OSKeyStore.cpp b/security/manager/ssl/OSKeyStore.cpp
--- a/security/manager/ssl/OSKeyStore.cpp
+++ b/security/manager/ssl/OSKeyStore.cpp
@@ -23,16 +23,18 @@
 #include "NSSKeyStore.h"
 #endif
 
 NS_IMPL_ISUPPORTS(OSKeyStore, nsIOSKeyStore, nsIObserver)
 
 using namespace mozilla;
 using dom::Promise;
 
+LazyLogModule gOSKeyStoreLog("oskeystore");
+
 OSKeyStore::OSKeyStore()
     : mKs(nullptr), mKsThread(nullptr), mKsIsNSSKeyStore(false) {
   MOZ_ASSERT(NS_IsMainThread());
   if (NS_WARN_IF(!NS_IsMainThread())) {
     return;
   }
 
 #if defined(XP_MACOSX)
@@ -117,31 +119,37 @@ nsresult OSKeyStore::SecretAvailable(con
 
 nsresult OSKeyStore::GenerateSecret(const nsACString& aLabel,
                                     /* out */ nsACString& aRecoveryPhrase) {
   NS_ENSURE_STATE(mKs);
   size_t keyByteLength = mKs->GetKeyByteLength();
   std::vector<uint8_t> secret(keyByteLength);
   nsresult rv = GenerateRandom(secret);
   if (NS_FAILED(rv) || secret.size() != keyByteLength) {
+    MOZ_LOG(gOSKeyStoreLog, LogLevel::Debug,
+            ("GenerateSecret: GenerateRandom failed"));
     return NS_ERROR_FAILURE;
   }
   nsAutoCString secretString;
   secretString.Assign(BitwiseCast<char*, uint8_t*>(secret.data()),
                       secret.size());
 
   nsAutoCString base64;
   rv = Base64Encode(secretString, base64);
   if (NS_FAILED(rv)) {
+    MOZ_LOG(gOSKeyStoreLog, LogLevel::Debug,
+            ("GenerateSecret: Base64Encode failed"));
     return rv;
   }
 
   nsAutoCString label = mLabelPrefix + aLabel;
   rv = mKs->StoreSecret(secretString, label);
   if (NS_FAILED(rv)) {
+    MOZ_LOG(gOSKeyStoreLog, LogLevel::Debug,
+            ("GenerateSecret: StoreSecret failed"));
     return rv;
   }
 
   aRecoveryPhrase = base64;
   return NS_OK;
 }
 
 nsresult OSKeyStore::RecoverSecret(const nsACString& aLabel,
@@ -339,16 +347,20 @@ OSKeyStore::AsyncLock(JSContext* aCx, Pr
   return mKsThread->Dispatch(runnable.forget());
 }
 
 void BackgroundGenerateSecret(const nsACString& aLabel,
                               RefPtr<Promise>& aPromise,
                               RefPtr<OSKeyStore> self) {
   nsAutoCString recovery;
   nsresult rv = self->GenerateSecret(aLabel, recovery);
+  if (NS_FAILED(rv)) {
+    MOZ_LOG(gOSKeyStoreLog, LogLevel::Debug,
+            ("BackgroundGenerateSecret: GenerateSecret failed"));
+  }
   nsAutoString recoveryString;
   if (NS_SUCCEEDED(rv)) {
     CopyUTF8toUTF16(recovery, recoveryString);
   }
   nsCOMPtr<nsIRunnable> runnable(NS_NewRunnableFunction(
       "BackgroundGenerateSecreteOSKSResolve",
       [rv, aPromise = std::move(aPromise), recoveryString]() {
         if (NS_FAILED(rv)) {
@@ -358,38 +370,46 @@ void BackgroundGenerateSecret(const nsAC
         }
       }));
   NS_DispatchToMainThread(runnable.forget());
 }
 
 NS_IMETHODIMP
 OSKeyStore::AsyncGenerateSecret(const nsACString& aLabel, JSContext* aCx,
                                 Promise** promiseOut) {
+  MOZ_LOG(gOSKeyStoreLog, LogLevel::Debug, ("AsyncGenerateSecret"));
   MOZ_ASSERT(NS_IsMainThread());
   if (!NS_IsMainThread()) {
+    MOZ_LOG(gOSKeyStoreLog, LogLevel::Debug,
+            ("AsyncGenerateSecret: not main thread"));
     return NS_ERROR_NOT_SAME_THREAD;
   }
 
   NS_ENSURE_ARG_POINTER(aCx);
+  MOZ_LOG(gOSKeyStoreLog, LogLevel::Debug, ("had aCx"));
   NS_ENSURE_STATE(mKsThread);
+  MOZ_LOG(gOSKeyStoreLog, LogLevel::Debug, ("had mKsThread"));
 
   RefPtr<Promise> promiseHandle;
   nsresult rv = GetPromise(aCx, promiseHandle);
   if (NS_FAILED(rv)) {
+    MOZ_LOG(gOSKeyStoreLog, LogLevel::Debug,
+            ("AsyncGenerateSecret: GetPromiseFailed"));
     return rv;
   }
 
   RefPtr<OSKeyStore> self = this;
   nsCOMPtr<nsIRunnable> runnable(NS_NewRunnableFunction(
       "BackgroundGenerateSecret",
       [self, promiseHandle, aLabel = nsAutoCString(aLabel)]() mutable {
         BackgroundGenerateSecret(aLabel, promiseHandle, self);
       }));
 
   promiseHandle.forget(promiseOut);
+  MOZ_LOG(gOSKeyStoreLog, LogLevel::Debug, ("returning"));
   return mKsThread->Dispatch(runnable.forget());
 }
 
 void BackgroundSecretAvailable(const nsACString& aLabel,
                                RefPtr<Promise>& aPromise,
                                RefPtr<OSKeyStore> self) {
   bool available = false;
   nsresult rv = self->SecretAvailable(aLabel, &available);
diff --git a/security/manager/ssl/tests/unit/test_oskeystore.js b/security/manager/ssl/tests/unit/test_oskeystore.js
--- a/security/manager/ssl/tests/unit/test_oskeystore.js
+++ b/security/manager/ssl/tests/unit/test_oskeystore.js
@@ -156,69 +156,8 @@ add_task(async function() {
     let ciphertext = await promise;
     ok(ciphertext, "We should have a ciphertext now.");
   } catch (e) {
     ok(false, "Error encrypting " + e);
   }
 
   await delete_all_secrets();
 });
-
-// Test that using a recovery phrase works.
-add_task(async function() {
-  await delete_all_secrets();
-
-  let keystore = Cc["@mozilla.org/security/oskeystore;1"]
-                   .getService(Ci.nsIOSKeyStore);
-
-  let recoveryPhrase = await keystore.asyncGenerateSecret(LABELS[0]);
-  ok(recoveryPhrase, "A recovery phrase should've been created.");
-
-  let text = new Uint8Array([0x01, 0x00, 0x01]);
-  let ciphertext = await keystore.asyncEncryptBytes(LABELS[0], text.length, text);
-  ok(ciphertext, "We should have a ciphertext now.");
-
-  await keystore.asyncDeleteSecret(LABELS[0]);
-  // Decrypting should fail after deleting the secret.
-  await keystore.asyncDecryptBytes(LABELS[0], ciphertext)
-    .then(() => ok(false, "decrypting didn't throw as expected after deleting the secret"))
-    .catch(() => ok(true, "decrypting threw as expected after deleting the secret"));
-
-  await keystore.asyncRecoverSecret(LABELS[0], recoveryPhrase);
-  let plaintext = await keystore.asyncDecryptBytes(LABELS[0], ciphertext);
-  ok(plaintext.toString() == text.toString(), "Decrypted plaintext should be the same as text.");
-
-  await delete_all_secrets();
-});
-
-// Test that trying to use a non-base64 recovery phrase fails.
-add_task(async function() {
-  await delete_all_secrets();
-
-  let keystore = Cc["@mozilla.org/security/oskeystore;1"]
-                   .getService(Ci.nsIOSKeyStore);
-  await keystore.asyncRecoverSecret(LABELS[0], "@##$^&*()#$^&*(@#%&*_")
-    .then(() => ok(false, "base64-decoding non-base64 should have failed but didn't"))
-    .catch(() => ok(true, "base64-decoding non-base64 failed as expected"));
-
-  ok(!await keystore.asyncSecretAvailable(LABELS[0]),
-     "we didn't recover a secret, so the secret shouldn't be available");
-  let recoveryPhrase = await keystore.asyncGenerateSecret(LABELS[0]);
-  ok(recoveryPhrase && recoveryPhrase.length > 0,
-     "we should be able to re-use that label to generate a new secret");
-  await delete_all_secrets();
-});
-
-// Test that "recovering" a zero-length secret doesn't throw but also doesn't result in that label
-// slot being unusable to store a new secret.
-add_task(async function() {
-  await delete_all_secrets();
-
-  let keystore = Cc["@mozilla.org/security/oskeystore;1"]
-                   .getService(Ci.nsIOSKeyStore);
-  await keystore.asyncRecoverSecret(LABELS[0], "");
-  ok(!await keystore.asyncSecretAvailable(LABELS[0]),
-     "'recovering' a zero-length secret doesn't throw, but the secret is not available");
-  let recoveryPhrase = await keystore.asyncGenerateSecret(LABELS[0]);
-  ok(recoveryPhrase && recoveryPhrase.length > 0,
-     "we should be able to re-use that label to generate a new secret");
-  await delete_all_secrets();
-});