[NearbyShare] Add logging to Certificate Manager and Certificate Storage

Log a variety of errors and the start/finish of async operations in
NearbyShareCertificateManagerImpl and NearbyShareCertificateStorageImpl
using the NS_LOG macro.

Change-Id: Iadbee4fff8869b23606b990f7635e3f73429dad8
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2364086
Commit-Queue: Curt Clemens <cclem@google.com>
Reviewed-by: Josh Nohle <nohle@chromium.org>
Cr-Commit-Position: refs/heads/master@{#800563}

chrome/browser/nearby_sharing/certificates/nearby_share_certificate_manager_impl.cc

@@ -8,6 +8,7 @@
 #include "base/callback.h"
 #include "base/memory/ptr_util.h"
 #include "base/notreached.h"
+#include "base/strings/string_number_conversions.h"
 #include "base/time/time.h"
 #include "chrome/browser/nearby_sharing/certificates/common.h"
 #include "chrome/browser/nearby_sharing/certificates/constants.h"
@@ -16,6 +17,7 @@
 #include "chrome/browser/nearby_sharing/common/nearby_share_http_result.h"
 #include "chrome/browser/nearby_sharing/common/nearby_share_prefs.h"
 #include "chrome/browser/nearby_sharing/local_device_data/nearby_share_local_device_data_manager.h"
+#include "chrome/browser/nearby_sharing/logging/logging.h"
 #include "chrome/browser/nearby_sharing/proto/certificate_rpc.pb.h"
 #include "chrome/browser/nearby_sharing/proto/encrypted_metadata.pb.h"
 #include "chrome/browser/nearby_sharing/scheduling/nearby_share_scheduler_factory.h"
@@ -33,6 +35,8 @@ void TryDecryptPublicCertificates(
     std::unique_ptr<std::vector<nearbyshare::proto::PublicCertificate>>
         public_certificates) {
   if (!success || !public_certificates) {
+    NS_LOG(ERROR) << __func__
+                  << ": Failed to read public certificates from storage.";
     std::move(callback).Run(base::nullopt);
     return;
   }
@@ -42,10 +46,16 @@ void TryDecryptPublicCertificates(
         NearbyShareDecryptedPublicCertificate::DecryptPublicCertificate(
             cert, encrypted_metadata_key);
     if (decrypted) {
+      NS_LOG(VERBOSE) << __func__
+                      << ": Successfully decrypted public certificate with ID "
+                      << base::HexEncode(decrypted->id());
       std::move(callback).Run(std::move(decrypted));
       return;
     }
   }
+  NS_LOG(VERBOSE)
+      << __func__
+      << ": Metadata key could not decrypt any public certificates.";
   std::move(callback).Run(base::nullopt);
 }
 
@@ -134,6 +144,9 @@ NearbyShareCertificateManagerImpl::GetValidPrivateCertificate(
     }
   }
   NOTREACHED();
+  NS_LOG(ERROR) << __func__
+                << ": No valid private certificate found with visibility "
+                << static_cast<int>(visibility);
   return NearbySharePrivateCertificate(NearbyShareVisibility::kNoOne,
                                        /*not_before=*/base::Time(),
                                        nearbyshare::proto::EncryptedMetadata());
@@ -171,6 +184,7 @@ void NearbyShareCertificateManagerImpl::OnDownloadPublicCertificatesRequest(
     request.add_secret_ids(id);
   }
 
+  NS_LOG(VERBOSE) << __func__ << ": Downloading public certificates.";
   // TODO(https://crbug.com/1116910): Enforce a timeout for each
   // ListPublicCertificates call.
   client_ = client_factory_->CreateInstance();
@@ -195,6 +209,8 @@ void NearbyShareCertificateManagerImpl::OnRpcSuccess(
 
   client_.reset();
 
+  NS_LOG(VERBOSE) << __func__ << ": " << certs.size()
+                  << " public certificates downloaded.";
   cert_store_->AddPublicCertificates(
       certs, base::BindOnce(
                  &NearbyShareCertificateManagerImpl::OnPublicCertificatesAdded,
@@ -222,6 +238,17 @@ void NearbyShareCertificateManagerImpl::OnPublicCertificatesAdded(
 void NearbyShareCertificateManagerImpl::FinishDownloadPublicCertificates(
     bool success,
     NearbyShareHttpResult http_result) {
+  if (success) {
+    NS_LOG(VERBOSE)
+        << __func__
+        << ": Public certificates successfully downloaded and stored.";
+  } else if (http_result == NearbyShareHttpResult::kSuccess) {
+    NS_LOG(ERROR) << __func__ << ": Public certificates not stored.";
+  } else {
+    NS_LOG(ERROR) << __func__
+                  << ": Public certificates download failed with HTTP error: "
+                  << http_result;
+  }
   RecordResultMetrics(http_result);
   download_public_certificates_scheduler_->HandleResult(success);
 }

chrome/browser/nearby_sharing/certificates/nearby_share_certificate_storage_impl.cc

@@ -20,6 +20,7 @@
 #include "chrome/browser/nearby_sharing/certificates/constants.h"
 #include "chrome/browser/nearby_sharing/certificates/nearby_share_private_certificate.h"
 #include "chrome/browser/nearby_sharing/common/nearby_share_prefs.h"
+#include "chrome/browser/nearby_sharing/logging/logging.h"
 #include "chrome/browser/nearby_sharing/proto/rpc_resources.pb.h"
 #include "components/leveldb_proto/public/proto_database_provider.h"
 #include "components/prefs/pref_registry_simple.h"
@@ -132,6 +133,10 @@ void NearbyShareCertificateStorageImpl::Initialize() {
         break;
       }
 
+      NS_LOG(VERBOSE) << __func__
+                      << ": Attempting to initialize public certificate "
+                         "database. Number of attempts: "
+                      << num_initialize_attempts_;
       db_->Init(base::BindOnce(
           &NearbyShareCertificateStorageImpl::OnDatabaseInitialized,
           base::Unretained(this)));
@@ -143,6 +148,9 @@ void NearbyShareCertificateStorageImpl::Initialize() {
 }
 
 void NearbyShareCertificateStorageImpl::DestroyAndReinitialize() {
+  NS_LOG(ERROR) << __func__
+                << ": Public certificate database corrupt. Erasing and "
+                   "initializing new database.";
   init_status_ = InitStatus::kUninitialized;
   db_->Destroy(base::BindOnce(
       &NearbyShareCertificateStorageImpl::OnDatabaseDestroyedReinitialize,
@@ -170,6 +178,13 @@ void NearbyShareCertificateStorageImpl::OnDatabaseInitialized(
 
 void NearbyShareCertificateStorageImpl::FinishInitialization(bool success) {
   init_status_ = success ? InitStatus::kInitialized : InitStatus::kFailed;
+  if (success) {
+    NS_LOG(VERBOSE) << __func__
+                    << "Public certificate database initialization succeeded.";
+  } else {
+    NS_LOG(ERROR) << __func__
+                  << "Public certificate database initialization failed.";
+  }
 
   // We run deferred callbacks even if initialization failed not to cause
   // possible client-side blocks of next calls to the database.
@@ -183,6 +198,8 @@ void NearbyShareCertificateStorageImpl::FinishInitialization(bool success) {
 void NearbyShareCertificateStorageImpl::OnDatabaseDestroyedReinitialize(
     bool success) {
   if (!success) {
+    NS_LOG(ERROR) << __func__
+                  << ": Failed to destroy public certificate database.";
     FinishInitialization(false);
     return;
   }
@@ -197,6 +214,8 @@ void NearbyShareCertificateStorageImpl::OnDatabaseDestroyed(
     ResultCallback callback,
     bool success) {
   if (!success) {
+    NS_LOG(ERROR) << __func__
+                  << ": Failed to destroy public certificate database.";
     std::move(callback).Run(false);
     return;
   }
@@ -220,6 +239,8 @@ void NearbyShareCertificateStorageImpl::
     return;
   }
 
+  NS_LOG(VERBOSE) << __func__ << ": Inserting " << new_entries->size()
+                  << " new public certificates.";
   db_->UpdateEntries(
       std::move(new_entries),
       /*keys_to_remove=*/std::make_unique<std::vector<std::string>>(),
@@ -235,9 +256,11 @@ void NearbyShareCertificateStorageImpl::
         ResultCallback callback,
         bool proceed) {
   if (!proceed) {
+    NS_LOG(ERROR) << __func__ << ": Failed to replace public certificates.";
     std::move(callback).Run(false);
     return;
   }
+  NS_LOG(VERBOSE) << __func__ << ": Successfully replaced public certificates.";
 
   CHECK(expirations);
   public_certificate_expirations_.swap(*expirations);
@@ -250,9 +273,11 @@ void NearbyShareCertificateStorageImpl::AddPublicCertificatesCallback(
     ResultCallback callback,
     bool proceed) {
   if (!proceed) {
+    NS_LOG(ERROR) << __func__ << ": Failed to add public certificates.";
     std::move(callback).Run(false);
     return;
   }
+  NS_LOG(VERBOSE) << __func__ << ": Successfully added public certificates.";
 
   public_certificate_expirations_ =
       MergeExpirations(public_certificate_expirations_, *new_expirations);
@@ -265,9 +290,13 @@ void NearbyShareCertificateStorageImpl::RemoveExpiredPublicCertificatesCallback(
     ResultCallback callback,
     bool proceed) {
   if (!proceed) {
+    NS_LOG(ERROR) << __func__
+                  << ": Failed to remove expired public certificates.";
     std::move(callback).Run(false);
     return;
   }
+  NS_LOG(VERBOSE) << __func__
+                  << ": Expired public certificates successfully removed.";
 
   auto should_remove =
       [&](const std::pair<std::string, base::Time>& pair) -> bool {
@@ -305,6 +334,7 @@ void NearbyShareCertificateStorageImpl::GetPublicCertificates(
     return;
   }
 
+  NS_LOG(VERBOSE) << __func__ << ": Calling LoadEntries on database.";
   db_->LoadEntries(std::move(callback));
 }
 
@@ -358,6 +388,8 @@ void NearbyShareCertificateStorageImpl::ReplacePrivateCertificates(
   for (const NearbySharePrivateCertificate& cert : private_certificates) {
     list.Append(cert.ToDictionary());
   }
+  NS_LOG(VERBOSE) << __func__ << ": Overwriting private certificates pref. "
+                  << private_certificates.size() << " new certificates.";
   pref_service_->Set(prefs::kNearbySharingPrivateCertificateListPrefName, list);
 }
 
@@ -388,6 +420,7 @@ void NearbyShareCertificateStorageImpl::ReplacePublicCertificates(
   }
   std::sort(new_expirations->begin(), new_expirations->end(), SortBySecond);
 
+  NS_LOG(VERBOSE) << __func__ << ": Clearing public certificate database.";
   db_->Destroy(base::BindOnce(&NearbyShareCertificateStorageImpl::
                                   ReplacePublicCertificatesDestroyCallback,
                               base::Unretained(this), std::move(new_entries),
@@ -421,6 +454,10 @@ void NearbyShareCertificateStorageImpl::AddPublicCertificates(
   }
   std::sort(new_expirations->begin(), new_expirations->end(), SortBySecond);
 
+  NS_LOG(VERBOSE)
+      << __func__
+      << ": Calling UpdateEntries on public certificate database with "
+      << public_certificates.size() << " new certificates.";
   db_->UpdateEntries(
       std::move(new_entries), std::make_unique<std::vector<std::string>>(),
       base::BindOnce(
@@ -462,6 +499,10 @@ void NearbyShareCertificateStorageImpl::RemoveExpiredPublicCertificates(
   auto ids_to_remove_set = std::make_unique<base::flat_set<std::string>>(
       ids_to_remove->begin(), ids_to_remove->end());
 
+  NS_LOG(VERBOSE)
+      << __func__
+      << ": Calling UpdateEntries on public certificate database to remove "
+      << ids_to_remove->size() << " expired certificates.";
   db_->UpdateEntries(
       std::move(ids_to_add), std::move(ids_to_remove),
       base::BindOnce(&NearbyShareCertificateStorageImpl::
@@ -488,6 +529,8 @@ void NearbyShareCertificateStorageImpl::ClearPublicCertificates(
     return;
   }
 
+  NS_LOG(VERBOSE) << __func__
+                  << ": Calling Destroy on public certificate database.";
   db_->Destroy(
       base::BindOnce(&NearbyShareCertificateStorageImpl::OnDatabaseDestroyed,
                      base::Unretained(this), std::move(callback)));