Add logging to help diagnose disappearing system token user certs

Temporarily add ChromeOS-only logging to diagnose certificates
disappearing from the system token:
(*) Log info about all all User certificates on chrome start up
(*) Log a message when a certificate is being deleted.

Bug: 844537
Test: Examine output of net_unittests --gtest_filter=*LogUserCerts*
Change-Id: Ie9f173573ba7e0704bc8e21462183390fac0c640
Reviewed-on: https://chromium-review.googlesource.com/1169478
Commit-Queue: Pavol Marko <pmarko@chromium.org>
Reviewed-by: Matt Mueller <mattm@chromium.org>
Reviewed-by: Xiyuan Xia <xiyuan@chromium.org>
Cr-Commit-Position: refs/heads/master@{#582896}

chrome/browser/chromeos/chrome_browser_main_chromeos.cc

@@ -533,6 +533,11 @@ class SystemTokenCertDBInitializer {
         std::move(system_slot) /* public_slot */,
         crypto::ScopedPK11Slot() /* private_slot */);
     database->SetSystemSlot(std::move(system_slot_copy));
+
+    // TODO(https://crbug.com/844537): Remove this after we've collected logs
+    // that show device-wide certificates disappearing.
+    database->LogUserCertificates("SystemTokenInitiallyLoaded");
+
     system_token_cert_database_ = std::move(database);
 
     VLOG(1) << "SystemTokenCertDBInitializer: Passing system token NSS "

net/cert/nss_cert_database.cc

@@ -133,7 +133,7 @@ void NSSCertDatabase::ListModules(std::vector<crypto::ScopedPK11Slot>* modules,
       PK11_GetAllTokens(CKM_INVALID_MECHANISM,
                         need_rw ? PR_TRUE : PR_FALSE,  // needRW
                         PR_TRUE,                       // loadCerts (unused)
-                        NULL));                        // wincx
+                        nullptr));                     // wincx
   if (!slot_list) {
     LOG(ERROR) << "PK11_GetAllTokens failed: " << PORT_GetError();
     return;
@@ -386,6 +386,9 @@ bool NSSCertDatabase::IsHardwareBacked(const CERTCertificate* cert) const {
   return slot && PK11_IsHW(slot);
 }
 
+void NSSCertDatabase::LogUserCertificates(const std::string& log_reason) const {
+}
+
 void NSSCertDatabase::AddObserver(Observer* observer) {
   observer_list_->AddObserver(observer);
 }
@@ -404,11 +407,11 @@ ScopedCERTCertificateList NSSCertDatabase::ListCertsImpl(
   base::ScopedBlockingCall scoped_blocking_call(base::BlockingType::MAY_BLOCK);
 
   ScopedCERTCertificateList certs;
-  CERTCertList* cert_list = NULL;
+  CERTCertList* cert_list = nullptr;
   if (slot)
     cert_list = PK11_ListCertsInSlot(slot.get());
   else
-    cert_list = PK11_ListCerts(PK11CertListUnique, NULL);
+    cert_list = PK11_ListCerts(PK11CertListUnique, nullptr);
 
   CERTCertListNode* node;
   for (node = CERT_LIST_HEAD(cert_list); !CERT_LIST_END(node, cert_list);
@@ -428,9 +431,24 @@ void NSSCertDatabase::NotifyCertRemovalAndCallBack(
 }
 
 void NSSCertDatabase::NotifyObserversCertDBChanged() {
+  LogUserCertificates("DBChanged");
+
   observer_list_->Notify(FROM_HERE, &Observer::OnCertDBChanged);
 }
 
+// static
+std::string NSSCertDatabase::GetCertIssuerCommonName(
+    const CERTCertificate* cert) {
+  char* nss_issuer_name = CERT_GetCommonName(&cert->issuer);
+  if (!nss_issuer_name)
+    return std::string();
+
+  std::string issuer_name = nss_issuer_name;
+  PORT_Free(nss_issuer_name);
+
+  return issuer_name;
+}
+
 // static
 bool NSSCertDatabase::DeleteCertAndKeyImpl(CERTCertificate* cert) {
   // This method may acquire the NSS lock or reenter this code via extension
@@ -439,14 +457,22 @@ bool NSSCertDatabase::DeleteCertAndKeyImpl(CERTCertificate* cert) {
   // capacity if this method takes too much time to run.
   base::ScopedBlockingCall scoped_blocking_call(base::BlockingType::MAY_BLOCK);
 
+#if defined(OS_CHROMEOS)
+  // TODO(https://crbug.com/844537): Remove this after we've collected logs that
+  // show device-wide certificates disappearing.
+  std::string issuer_name = GetCertIssuerCommonName(cert);
+  VLOG(0) << "UserCertLogging: Deleting a certificate with issuer_name="
+          << issuer_name;
+#endif  // defined(OS_CHROMEOS)
+
   // For some reason, PK11_DeleteTokenCertAndKey only calls
   // SEC_DeletePermCertificate if the private key is found.  So, we check
   // whether a private key exists before deciding which function to call to
   // delete the cert.
-  SECKEYPrivateKey* privKey = PK11_FindKeyByAnyCert(cert, NULL);
+  SECKEYPrivateKey* privKey = PK11_FindKeyByAnyCert(cert, nullptr);
   if (privKey) {
     SECKEY_DestroyPrivateKey(privKey);
-    if (PK11_DeleteTokenCertAndKey(cert, NULL)) {
+    if (PK11_DeleteTokenCertAndKey(cert, nullptr)) {
       LOG(ERROR) << "PK11_DeleteTokenCertAndKey failed: " << PORT_GetError();
       return false;
     }

net/cert/nss_cert_database.h

@@ -232,6 +232,13 @@ class NET_EXPORT NSSCertDatabase {
   // Check whether cert is stored in a hardware slot.
   bool IsHardwareBacked(const CERTCertificate* cert) const;
 
+  // TODO(https://crbug.com/844537): Remove this after we've collected logs that
+  // show device-wide certificates disappearing. Does nothing in the default
+  // implementation, but can be used in subclasses for logging user
+  // certificates. Will be called when the DB has changed. |log_reason| says why
+  // this has been invoked.
+  virtual void LogUserCertificates(const std::string& log_reason) const;
+
  protected:
   // Certificate listing implementation used by |ListCerts*| and
   // |ListCertsSync|. Static so it may safely be used on the worker thread.
@@ -239,10 +246,13 @@ class NET_EXPORT NSSCertDatabase {
   // |slot|.
   static ScopedCERTCertificateList ListCertsImpl(crypto::ScopedPK11Slot slot);
 
- protected:
   // Broadcasts notifications to all registered observers.
   void NotifyObserversCertDBChanged();
 
+  // TODO(https://crbug.com/844537): Remove this after we've collected logs that
+  // show device-wide certificates disappearing.
+  static std::string GetCertIssuerCommonName(const CERTCertificate* cert);
+
  private:
   // Registers |observer| to receive notifications of certificate changes.  The
   // thread on which this is called is the thread on which |observer| will be

net/cert/nss_cert_database_chromeos.cc

@@ -5,6 +5,7 @@
 #include "net/cert/nss_cert_database_chromeos.h"
 
 #include <cert.h>
+#include <certdb.h>
 #include <pk11pub.h>
 
 #include <algorithm>
@@ -15,7 +16,9 @@
 #include "base/callback.h"
 #include "base/location.h"
 #include "base/stl_util.h"
+#include "base/strings/string_number_conversions.h"
 #include "base/task/post_task.h"
+#include "base/task/task_scheduler/task_scheduler.h"
 #include "base/threading/scoped_blocking_call.h"
 
 namespace net {
@@ -40,11 +43,13 @@ void NSSCertDatabaseChromeOS::SetSystemSlot(
 }
 
 ScopedCERTCertificateList NSSCertDatabaseChromeOS::ListCertsSync() {
+  LogUserCertificates("ListCertsSync");
   return ListCertsImpl(profile_filter_);
 }
 
 void NSSCertDatabaseChromeOS::ListCerts(
     const NSSCertDatabase::ListCertsCallback& callback) {
+  LogUserCertificates("ListCerts");
   base::PostTaskWithTraitsAndReplyWithResult(
       FROM_HERE,
       {base::MayBlock(), base::TaskShutdownBehavior::CONTINUE_ON_SHUTDOWN},
@@ -58,6 +63,21 @@ crypto::ScopedPK11Slot NSSCertDatabaseChromeOS::GetSystemSlot() const {
   return crypto::ScopedPK11Slot();
 }
 
+void NSSCertDatabaseChromeOS::LogUserCertificates(
+    const std::string& log_reason) const {
+  // Unit tests may not have a TaskScheduler instance.
+  if (!base::TaskScheduler::GetInstance())
+    return;
+
+  crypto::ScopedPK11Slot system_slot(GetSystemSlot());
+
+  base::PostTaskWithTraits(
+      FROM_HERE,
+      {base::MayBlock(), base::TaskShutdownBehavior::CONTINUE_ON_SHUTDOWN},
+      base::BindOnce(&NSSCertDatabaseChromeOS::LogUserCertificatesImpl,
+                     log_reason, base::Passed(&system_slot)));
+}
+
 void NSSCertDatabaseChromeOS::ListModules(
     std::vector<crypto::ScopedPK11Slot>* modules,
     bool need_rw) const {
@@ -91,4 +111,72 @@ ScopedCERTCertificateList NSSCertDatabaseChromeOS::ListCertsImpl(
   return certs;
 }
 
+// static
+void NSSCertDatabaseChromeOS::LogUserCertificatesImpl(
+    const std::string& log_reason,
+    crypto::ScopedPK11Slot system_slot) {
+  // See ListCertsImpl for details on why we use |MAY_BLOCK|.
+  base::ScopedBlockingCall scoped_blocking_call(base::BlockingType::MAY_BLOCK);
+
+  bool system_slot_present = system_slot != nullptr;
+  VLOG(0) << "UserCertLogging: Invoked with log_reason=" << log_reason
+          << ", system_slot_present=" << system_slot_present;
+
+  CERTCertList* cert_list = PK11_ListCerts(PK11CertListUnique, nullptr);
+  CERTCertListNode* node;
+  for (node = CERT_LIST_HEAD(cert_list); !CERT_LIST_END(node, cert_list);
+       node = CERT_LIST_NEXT(node)) {
+    CERTCertificate* cert = node->cert;
+
+    // Skip if the certificate is not a user certificate, or if this can't be
+    // determined.
+    CERTCertTrust nss_trust;
+    SECStatus rv = CERT_GetCertTrust(cert, &nss_trust);
+    if (rv != SECSuccess) {
+      LOG(ERROR) << "CERT_GetCertTrust failed with error " << PORT_GetError();
+      continue;
+    }
+    unsigned int all_flags = nss_trust.sslFlags | nss_trust.emailFlags |
+                             nss_trust.objectSigningFlags;
+    // This logic is from |mozilla_security_manager::GetCertType|.
+    bool is_user_cert = cert->nickname && (all_flags & CERTDB_USER);
+    if (!is_user_cert)
+      continue;
+
+    // Get names from the certificate. Only log issuer CommonName for now.
+    std::string issuer_name = GetCertIssuerCommonName(cert);
+
+    // Get information about the slot the certificate is on.
+    PK11SlotInfo* slot = cert->slot;
+    bool is_hardware_backed = slot && PK11_IsHW(slot);
+    bool is_on_system_slot = slot == system_slot.get();
+    int cert_slot_id = static_cast<int>(PK11_GetSlotID(slot));
+
+    // Get information about the corresponding private key: the slot id it is on
+    // and the pkcs11 object ID.
+    int key_slot_id = -1;
+    std::string key_pkcs11_id;
+    SECKEYPrivateKey* private_key =
+        PK11_FindKeyByAnyCert(cert, nullptr /* wincx */);
+    if (private_key) {
+      key_slot_id = static_cast<int>(PK11_GetSlotID(private_key->pkcs11Slot));
+      // Get the CKA_ID attribute for a key.
+      SECItem* sec_item = PK11_GetLowLevelKeyIDForPrivateKey(private_key);
+      if (sec_item) {
+        key_pkcs11_id = base::HexEncode(sec_item->data, sec_item->len);
+        SECITEM_FreeItem(sec_item, PR_TRUE);
+      }
+      SECKEY_DestroyPrivateKey(private_key);
+    }
+
+    VLOG(0) << "UserCertLogging: Cert with issuer=" << issuer_name
+            << ", cert_slot_id=" << cert_slot_id
+            << ", is_hw_backed=" << is_hardware_backed
+            << ", is_on_system_slot=" << is_on_system_slot
+            << ", key_slot_id=" << key_slot_id
+            << ", key_pkcs11_id=" << key_pkcs11_id;
+  }
+  CERT_DestroyCertList(cert_list);
+}
+
 }  // namespace net

net/cert/nss_cert_database_chromeos.h

@@ -36,6 +36,11 @@ class NET_EXPORT NSSCertDatabaseChromeOS : public NSSCertDatabase {
   // in multiple slots.
   // TODO(mattm): handle trust setting correctly for certs in read-only slots.
 
+  // TODO(https://crbug.com/844537): Remove this after we've collected logs that
+  // show device-wide certificates disappearing. Logs basic information about
+  // known user certificates.
+  void LogUserCertificates(const std::string& log_reason) const override;
+
  private:
   // Certificate listing implementation used by |ListCerts| and |ListCertsSync|.
   // The certificate list normally returned by NSSCertDatabase::ListCertsImpl
@@ -44,6 +49,11 @@ class NET_EXPORT NSSCertDatabaseChromeOS : public NSSCertDatabase {
   static ScopedCERTCertificateList ListCertsImpl(
       const NSSProfileFilterChromeOS& profile_filter);
 
+  // TODO(https://crbug.com/844537): Remove this after we've collected logs that
+  // show device-wide certificates disappearing.
+  static void LogUserCertificatesImpl(const std::string& log_reason,
+                                      crypto::ScopedPK11Slot system_slot);
+
   NSSProfileFilterChromeOS profile_filter_;
   crypto::ScopedPK11Slot system_slot_;
 

net/cert/nss_cert_database_chromeos_unittest.cc

@@ -286,6 +286,20 @@ TEST_F(NSSCertDatabaseChromeOSTest, ListCertsReadsSystemSlot) {
   EXPECT_TRUE(IsCertInCertificateList(cert_2.get(), certs));
 }
 
+// TODO(https://crbug.com/844537): Remove this after we've collected logs that
+// show device-wide certificates disappearing.
+TEST_F(NSSCertDatabaseChromeOSTest, LogUserCerts) {
+  scoped_refptr<X509Certificate> cert_1(ImportClientCertAndKeyFromFile(
+      GetTestCertsDirectory(), "client_1.pem", "client_1.pk8",
+      db_1_->GetPublicSlot().get()));
+
+  scoped_refptr<X509Certificate> cert_2(ImportClientCertAndKeyFromFile(
+      GetTestCertsDirectory(), "client_2.pem", "client_2.pk8",
+      db_1_->GetSystemSlot().get()));
+  db_1_->LogUserCertificates("UnitTest");
+  RunUntilIdle();
+}
+
 TEST_F(NSSCertDatabaseChromeOSTest, ListCertsDoesNotCrossReadSystemSlot) {
   scoped_refptr<X509Certificate> cert_1(
       ImportClientCertAndKeyFromFile(GetTestCertsDirectory(),