Add Krb5CredentialsCacheManagerLogger for logging credential cache in…

…formation

Summary:
This patch adds the Krb5CredentialsCacheManagerLogger interface for logging credential cache data in the
Krb5CredentialsCacheManager. This will allow users to log specific data about the credential cache like keytab,
default principal and service ticket expiration times.

Reviewed By: abajenov

Differential Revision: D4349976

fbshipit-source-id: 840ad59c5f6353c66fe9d06abde1d09b27972ed4

thrift/lib/cpp/Makefile.am

@@ -235,7 +235,8 @@ include_utilkerberos_HEADERS = \
 	util/kerberos/FBKrb5GetCreds.h \
 	util/kerberos/Krb5OlderVersionStubs.h \
 	util/kerberos/Krb5Tgts.h \
-	util/kerberos/Krb5Util.h
+	util/kerberos/Krb5Util.h \
+	util/kerberos/Krb5CredentialsCacheManagerLogger.h
 
 include_testdir = $(include_thriftdir)/test
 include_test_HEADERS = \

thrift/lib/cpp/util/kerberos/Krb5CCacheStore.cpp

@@ -73,7 +73,8 @@ uint64_t Krb5CCacheStore::ServiceData::getCount() {
 
 std::shared_ptr<Krb5CCache> Krb5CCacheStore::waitForCache(
     const Krb5Principal& service,
-    SecurityLogger* logger) {
+    SecurityLogger* logger,
+    bool* didInitCacheForService) {
   std::shared_ptr<ServiceData> dataPtr = getServiceDataPtr(service);
 
   uint64_t curtime = chrono::duration_cast<chrono::seconds>(
@@ -97,6 +98,9 @@ std::shared_ptr<Krb5CCache> Krb5CCacheStore::waitForCache(
         if (logger) {
           logger->logEnd("get_prepared_cache");
         }
+        if (didInitCacheForService) {
+          *didInitCacheForService = false;
+        }
         return dataPtr->cache;
       }
     }
@@ -120,6 +124,10 @@ std::shared_ptr<Krb5CCache> Krb5CCacheStore::waitForCache(
   dataPtr->cache = std::move(tempCache);
   dataPtr->expires = expires;
 
+  if (didInitCacheForService) {
+    *didInitCacheForService = true;
+  }
+
   return dataPtr->cache;
 }
 
@@ -361,6 +369,29 @@ uint64_t Krb5CCacheStore::renewCreds() {
   return renewCount;
 }
 
+std::set<std::string> Krb5CCacheStore::getTopServices(size_t limit) {
+  // Put 'limit' number of most frequently used credentials into the
+  // top_services set.
+  folly::SharedMutex::ReadHolder readLock(serviceDataMapLock_);
+  vector<pair<string, uint64_t>> count_vector;
+  for (auto& element : serviceDataMap_) {
+    count_vector.emplace_back(element.first, element.second->getCount());
+  }
+
+  sort(count_vector.begin(), count_vector.end(), serviceCountCompare);
+
+  std::set<std::string> top_services;
+  int count = 0;
+  for (auto& element : count_vector) {
+    if (count >= limit) {
+      break;
+    }
+    top_services.insert(element.first);
+    count++;
+  }
+  return top_services;
+}
+
 std::unique_ptr<Krb5CCache> Krb5CCacheStore::exportCache(size_t limit) {
   Krb5Principal client_principal = tgts_.getClientPrincipal();
 
@@ -371,25 +402,8 @@ std::unique_ptr<Krb5CCache> Krb5CCacheStore::exportCache(size_t limit) {
   temp_cache->initialize(client_principal.get());
 
   {
-    // Put 'limit' number of most frequently used credentials into the
-    // top_services set.
     folly::SharedMutex::ReadHolder readLock(serviceDataMapLock_);
-    vector<pair<string, uint64_t>> count_vector;
-    for (auto& element : serviceDataMap_) {
-      count_vector.emplace_back(element.first, element.second->getCount());
-    }
-
-    sort(count_vector.begin(), count_vector.end(), serviceCountCompare);
-
-    std::set<string> top_services;
-    int count = 0;
-    for (auto& element : count_vector) {
-      if (count >= limit) {
-        break;
-      }
-      top_services.insert(element.first);
-      count++;
-    }
+    const auto top_services = getTopServices(limit);
 
     for (auto& data : serviceDataMap_) {
       folly::SharedMutex::ReadHolder lock(data.second->lockCache);
@@ -424,7 +438,7 @@ bool Krb5CCacheStore::isInitialized() {
   return tgts_.isInitialized();
 }
 
-std::pair<uint64_t, uint64_t> Krb5CCacheStore::getLifetime() {
+Krb5Lifetime Krb5CCacheStore::getLifetime() {
   return tgts_.getLifetime();
 }
 
@@ -444,4 +458,42 @@ void Krb5CCacheStore::notifyOfError(const std::string& error) {
   tgts_.notifyOfError(error);
 }
 
+std::map<std::string, Krb5Lifetime>
+Krb5CCacheStore::getServicePrincipalLifetimes(size_t limit) {
+  folly::SharedMutex::ReadHolder readLock(serviceDataMapLock_);
+  const auto top_services = getTopServices(limit);
+
+  std::map<std::string, Krb5Lifetime> services;
+  for (auto& data : serviceDataMap_) {
+    folly::SharedMutex::ReadHolder cache_lock(data.second->lockCache);
+    if (!data.second->cache) {
+      continue;
+    }
+    const auto service = getLifetimeOfFirstServicePrincipal(data.second->cache);
+    if (top_services.count(service.first) == 0) {
+      continue;
+    }
+    services[service.first] = service.second;
+  }
+  return services;
+}
+
+std::map<std::string, Krb5Lifetime> Krb5CCacheStore::getTgtLifetimes() {
+  return tgts_.getLifetimes();
+}
+
+std::pair<std::string, Krb5Lifetime>
+Krb5CCacheStore::getLifetimeOfFirstServicePrincipal(
+    const std::shared_ptr<Krb5CCache>& cache) {
+  auto princ_list = cache->getServicePrincipalList();
+  if (princ_list.size() < 1) {
+    throw std::runtime_error("Principal list too small in ccache");
+  }
+  auto princ = std::move(princ_list[0]);
+  auto princStr = folly::to<string>(princ);
+  auto creds = cache->retrieveCred(princ.get());
+  auto lifetime =
+      std::make_pair(creds.get().times.starttime, creds.get().times.endtime);
+  return std::make_pair(folly::to<string>(princ), std::move(lifetime));
+}
 }}}

thrift/lib/cpp/util/kerberos/Krb5CCacheStore.h

@@ -17,10 +17,11 @@
 #ifndef KRB5_CCACHE_STORE
 #define KRB5_CCACHE_STORE
 
+#include <krb5.h>
 #include <condition_variable>
 #include <iostream>
-#include <krb5.h>
 #include <queue>
+#include <set>
 #include <string>
 #include <thread>
 #include <unordered_map>
@@ -48,8 +49,9 @@ class Krb5CCacheStore {
   virtual ~Krb5CCacheStore() {}
 
   std::shared_ptr<Krb5CCache> waitForCache(
-    const Krb5Principal& service,
-    SecurityLogger* logger = nullptr);
+      const Krb5Principal& service,
+      SecurityLogger* logger = nullptr,
+      bool* didInitCacheForService = nullptr);
 
   void kInit(const Krb5Principal& client);
   bool isInitialized();
@@ -66,7 +68,13 @@ class Krb5CCacheStore {
   /**
    * Get lifetime of the currently loaded creds.
    */
-  std::pair<uint64_t, uint64_t> getLifetime();
+  Krb5Lifetime getLifetime();
+
+  std::map<std::string, Krb5Lifetime> getServicePrincipalLifetimes(
+      size_t limit);
+  std::pair<std::string, Krb5Lifetime> getLifetimeOfFirstServicePrincipal(
+      const std::shared_ptr<Krb5CCache>& cache);
+  std::map<std::string, Krb5Lifetime> getTgtLifetimes();
 
  protected:
   static const int SERVICE_HISTOGRAM_NUM_BUCKETS;
@@ -104,6 +112,7 @@ class Krb5CCacheStore {
 
   std::shared_ptr<ServiceData> getServiceDataPtr(const Krb5Principal& service);
   std::vector<Krb5Principal> getServicePrincipalList();
+  std::set<std::string> getTopServices(size_t limit);
 
   void raiseIf(krb5_error_code code, const std::string& what) {
     apache::thrift::krb5::raiseIf(ctx_.get(), code, what);

thrift/lib/cpp/util/kerberos/Krb5CredentialsCacheManager.cpp

@@ -53,14 +53,15 @@ using namespace std;
 const int Krb5CredentialsCacheManager::MANAGE_THREAD_SLEEP_PERIOD = 10*60*1000;
 const int Krb5CredentialsCacheManager::ABOUT_TO_EXPIRE_THRESHOLD = 600;
 const int Krb5CredentialsCacheManager::NUM_ELEMENTS_TO_PERSIST_TO_FILE = 10000;
+const int Krb5CredentialsCacheManager::NUM_ELEMENTS_TO_LOG = 10;
 
 Krb5CredentialsCacheManager::Krb5CredentialsCacheManager(
-  const std::shared_ptr<SecurityLogger>& logger,
-  int maxCacheSize)
-    : stopManageThread_(false)
-    , logger_(logger)
-    , ccacheTypeIsMemory_(false)
-    , updateFileCacheEnabled_(true) {
+    const std::shared_ptr<Krb5CredentialsCacheManagerLogger>& logger,
+    int maxCacheSize)
+    : stopManageThread_(false),
+      logger_(logger),
+      ccacheTypeIsMemory_(false),
+      updateFileCacheEnabled_(true) {
   try {
     // These calls can throw if the context cannot be initialized for some
     // reason, e.g. bad config format, etc.
@@ -123,10 +124,12 @@ Krb5CredentialsCacheManager::Krb5CredentialsCacheManager(
           logger->logStart("init_cache_store");
           initCacheStore();
           logger->logEnd("init_cache_store");
+          logTopCredentials(logger, "init_cache_store");
         } else if (aboutToExpire(store_->getLifetime())) {
           logger->logStart("init_cache_store", "expired");
           initCacheStore();
           logger->logEnd("init_cache_store");
+          logTopCredentials(logger, "init_expired_cache_store");
         }
 
         // If not a user credential and the cache store needs to be renewed,
@@ -141,6 +144,7 @@ Krb5CredentialsCacheManager::Krb5CredentialsCacheManager(
             uint64_t renewCount = store_->renewCreds();
             logger->logEnd(
               "build_renewed_cache", folly::to<std::string>(renewCount));
+            logTopCredentials(logger, "build_renewed_cache");
           }
 
           if (updateFileCacheEnabled_) {
@@ -412,9 +416,9 @@ int Krb5CredentialsCacheManager::writeOutCache(size_t limit) {
     LOG(ERROR) << "Could not open a temporary cache file with template: "
                << tmp_template << " error: " << strerror(errno);
     logger_->log(
-      "persist_ccache_fail_tmp_file_create_fail",
-      {tmp_template, strerror(errno)},
-      SecurityLogger::TracingOptions::NONE);
+        "persist_ccache_fail_tmp_file_create_fail",
+        {tmp_template, strerror(errno)},
+        Krb5CredentialsCacheManagerLogger::TracingOptions::NONE);
     return -1;
   }
   ret = close(fd);
@@ -475,7 +479,12 @@ std::shared_ptr<Krb5CCache> Krb5CredentialsCacheManager::waitForCache(
   if (!store_) {
     throw std::runtime_error("Kerberos ccache store could not be initialized");
   }
-  return store_->waitForCache(service, logger);
+  bool didInitCacheForService;
+  auto cache = store_->waitForCache(service, logger, &didInitCacheForService);
+  if (didInitCacheForService) {
+    logOneCredential(logger_, "init_cache_for_service", cache);
+  }
+  return cache;
 }
 
 void Krb5CredentialsCacheManager::initCacheStore() {
@@ -560,8 +569,7 @@ bool Krb5CredentialsCacheManager::isPrincipalInKeytab(
   return false;
 }
 
-bool Krb5CredentialsCacheManager::aboutToExpire(
-    const std::pair<uint64_t, uint64_t>& lifetime) {
+bool Krb5CredentialsCacheManager::aboutToExpire(const Krb5Lifetime& lifetime) {
   time_t now;
   time(&now);
   return ((uint64_t) now +
@@ -570,7 +578,8 @@ bool Krb5CredentialsCacheManager::aboutToExpire(
 }
 
 bool Krb5CredentialsCacheManager::reachedRenewTime(
-    const std::pair<uint64_t, uint64_t>& lifetime, const std::string& client) {
+    const Krb5Lifetime& lifetime,
+    const std::string& client) {
   time_t now;
   time(&now);
   size_t sname_hash = std::hash<std::string>()(client);
@@ -585,4 +594,38 @@ bool Krb5CredentialsCacheManager::reachedRenewTime(
   return (uint64_t) now > (half_life_time + renew_offset);
 }
 
+void Krb5CredentialsCacheManager::logTopCredentials(
+    const std::shared_ptr<Krb5CredentialsCacheManagerLogger>& logger,
+    const std::string& key) {
+  logCredentialsCache(
+      logger,
+      key,
+      store_->getServicePrincipalLifetimes(
+          Krb5CredentialsCacheManager::NUM_ELEMENTS_TO_LOG));
+}
+
+void Krb5CredentialsCacheManager::logOneCredential(
+    const std::shared_ptr<Krb5CredentialsCacheManagerLogger>& logger,
+    const std::string& key,
+    const std::shared_ptr<Krb5CCache>& cache) {
+  const auto service = store_->getLifetimeOfFirstServicePrincipal(cache);
+  std::map<std::string, Krb5Lifetime> serviceLifetimes = {
+      {service.first, service.second}};
+
+  logCredentialsCache(logger, key, serviceLifetimes);
+}
+
+void Krb5CredentialsCacheManager::logCredentialsCache(
+    const std::shared_ptr<Krb5CredentialsCacheManagerLogger>& logger,
+    const std::string& key,
+    const std::map<std::string, Krb5Lifetime>& serviceLifetimes) {
+  Krb5Keytab keytab(ctx_->get());
+  logger->logCredentialsCache(
+      key,
+      keytab,
+      store_->getClientPrincipal(),
+      store_->getLifetime(),
+      serviceLifetimes,
+      store_->getTgtLifetimes());
+}
 }}}

thrift/lib/cpp/util/kerberos/Krb5CredentialsCacheManager.h

@@ -25,11 +25,12 @@
 #include <unordered_map>
 #include <chrono>
 
-#include <folly/stats/BucketedTimeSeries.h>
 #include <folly/RWSpinLock.h>
-#include <thrift/lib/cpp2/security/SecurityLogger.h>
+#include <folly/stats/BucketedTimeSeries.h>
 #include <thrift/lib/cpp/util/kerberos/Krb5CCacheStore.h>
+#include <thrift/lib/cpp/util/kerberos/Krb5CredentialsCacheManagerLogger.h>
 #include <thrift/lib/cpp/util/kerberos/Krb5Util.h>
+#include <thrift/lib/cpp2/security/SecurityLogger.h>
 
 namespace apache { namespace thrift { namespace krb5 {
 
@@ -44,9 +45,9 @@ class Krb5CredentialsCacheManager {
    * The logger object here will log internal events happening in the class.
    */
   explicit Krb5CredentialsCacheManager(
-    const std::shared_ptr<SecurityLogger>& logger =
-      std::make_shared<SecurityLogger>(),
-    int maxCacheSize = -1);
+      const std::shared_ptr<Krb5CredentialsCacheManagerLogger>& logger =
+          std::make_shared<Krb5CredentialsCacheManagerLogger>(),
+      int maxCacheSize = -1);
 
   virtual ~Krb5CredentialsCacheManager();
 
@@ -80,6 +81,7 @@ class Krb5CredentialsCacheManager {
   static const int MANAGE_THREAD_SLEEP_PERIOD;
   static const int ABOUT_TO_EXPIRE_THRESHOLD;
   static const int NUM_ELEMENTS_TO_PERSIST_TO_FILE;
+  static const int NUM_ELEMENTS_TO_LOG;
 
   /**
    * Read in credentials from the default CC file. Throws if
@@ -106,9 +108,22 @@ class Krb5CredentialsCacheManager {
 
   void initCacheStore();
 
-  bool aboutToExpire(const std::pair<uint64_t, uint64_t>& lifetime);
+  bool aboutToExpire(const Krb5Lifetime& lifetime);
   bool reachedRenewTime(
-    const std::pair<uint64_t, uint64_t>& lifetime, const std::string& client);
+      const Krb5Lifetime& lifetime,
+      const std::string& client);
+
+  void logTopCredentials(
+      const std::shared_ptr<Krb5CredentialsCacheManagerLogger>& logger,
+      const std::string& key);
+  void logOneCredential(
+      const std::shared_ptr<Krb5CredentialsCacheManagerLogger>& logger,
+      const std::string& key,
+      const std::shared_ptr<Krb5CCache>& cache);
+  void logCredentialsCache(
+      const std::shared_ptr<Krb5CredentialsCacheManagerLogger>& logger,
+      const std::string& key,
+      const std::map<std::string, Krb5Lifetime>& serviceLifetimes);
 
   std::unique_ptr<Krb5Context> ctx_;
 
@@ -121,7 +136,7 @@ class Krb5CredentialsCacheManager {
   Mutex manageThreadMutex_; // A lock for the two members below
   bool stopManageThread_;
   std::condition_variable manageThreadCondVar_;
-  std::shared_ptr<SecurityLogger> logger_;
+  std::shared_ptr<Krb5CredentialsCacheManagerLogger> logger_;
 
   bool ccacheTypeIsMemory_;
   bool updateFileCacheEnabled_;