log a structured event when a proxy hash lookup fails

Summary:
We don't have data on how often this repo-corrupted event occurs, so
begin logging it.

Reviewed By: xavierd

Differential Revision: D26968638

fbshipit-source-id: 95e62a595f74f22fdec8a60ebb0671e53cbe199e

eden/fs/config/EdenConfig.h

@@ -320,6 +320,15 @@ class EdenConfig : private ConfigSettingManager {
       false,
       this};
 
+  /**
+   * The minimum duration between logging occurrences of failed HgProxyHash
+   * loads.
+   */
+  ConfigSetting<std::chrono::nanoseconds> missingHgProxyHashLogInterval{
+      "store:missing-hgproxyhash-log-interval",
+      std::chrono::minutes{10},
+      this};
+
   /**
    * The maximum time duration allowed for a fuse request. If a request exceeds
    * this amount of time, an ETIMEDOUT error will be returned to the kernel to

eden/fs/service/EdenServer.cpp

@@ -1630,6 +1630,7 @@ shared_ptr<BackingStore> EdenServer::createBackingStore(
         getSharedStats(),
         std::move(store),
         reloadableConfig,
+        serverState_->getStructuredLogger(),
         std::make_unique<BackingStoreLogger>(
             serverState_->getStructuredLogger(),
             serverState_->getProcessNameCache()));

eden/fs/store/hg/HgQueuedBackingStore.cpp

@@ -29,6 +29,7 @@
 #include "eden/fs/store/hg/HgProxyHash.h"
 #include "eden/fs/telemetry/EdenStats.h"
 #include "eden/fs/telemetry/RequestMetricsScope.h"
+#include "eden/fs/telemetry/StructuredLogger.h"
 #include "eden/fs/utils/Bug.h"
 #include "eden/fs/utils/EnumValue.h"
 #include "eden/fs/utils/IDGen.h"
@@ -69,12 +70,14 @@ HgQueuedBackingStore::HgQueuedBackingStore(
     std::shared_ptr<EdenStats> stats,
     std::unique_ptr<HgBackingStore> backingStore,
     std::shared_ptr<ReloadableConfig> config,
+    std::shared_ptr<StructuredLogger> structuredLogger,
     std::unique_ptr<BackingStoreLogger> logger,
     uint8_t numberThreads)
     : localStore_(std::move(localStore)),
       stats_(std::move(stats)),
       config_(std::move(config)),
       backingStore_(std::move(backingStore)),
+      structuredLogger_{std::move(structuredLogger)},
       logger_(std::move(logger)),
       traceBus_{TraceBus<HgImportTraceEvent>::create("hg", kTraceBusCapacity)} {
   threads_.reserve(numberThreads);
@@ -220,7 +223,13 @@ void HgQueuedBackingStore::processRequest() {
 folly::SemiFuture<std::unique_ptr<Tree>> HgQueuedBackingStore::getTree(
     const Hash& id,
     ObjectFetchContext& context) {
-  auto proxyHash = HgProxyHash::load(localStore_.get(), id, "getTree");
+  HgProxyHash proxyHash;
+  try {
+    proxyHash = HgProxyHash::load(localStore_.get(), id, "getTree");
+  } catch (const std::exception&) {
+    logMissingProxyHash();
+    throw;
+  }
 
   // TODO: Merge checkTreeImportInProgress and enqueue into one call that
   // acquires the lock, and then atomically either schedules work or
@@ -269,7 +278,13 @@ folly::SemiFuture<std::unique_ptr<Tree>> HgQueuedBackingStore::getTree(
 folly::SemiFuture<std::unique_ptr<Blob>> HgQueuedBackingStore::getBlob(
     const Hash& id,
     ObjectFetchContext& context) {
-  auto proxyHash = HgProxyHash::load(localStore_.get(), id, "getBlob");
+  HgProxyHash proxyHash;
+  try {
+    proxyHash = HgProxyHash::load(localStore_.get(), id, "getBlob");
+  } catch (const std::exception&) {
+    logMissingProxyHash();
+    throw;
+  }
 
   auto path = proxyHash.path();
   logBackingStoreFetch(
@@ -347,7 +362,14 @@ folly::SemiFuture<folly::Unit> HgQueuedBackingStore::prefetchBlobs(
     });
   }
 
-  auto proxyHashes = HgProxyHash::getBatch(localStore_.get(), ids).get();
+  std::vector<HgProxyHash> proxyHashes;
+  try {
+    // TODO: Use .thenTry instead of .get()
+    proxyHashes = HgProxyHash::getBatch(localStore_.get(), ids).get();
+  } catch (const std::exception&) {
+    logMissingProxyHash();
+    throw;
+  }
 
   // TODO: deduplicate prefetches
 
@@ -366,6 +388,25 @@ folly::SemiFuture<folly::Unit> HgQueuedBackingStore::prefetchBlobs(
   return std::move(future);
 }
 
+void HgQueuedBackingStore::logMissingProxyHash() {
+  auto now = std::chrono::steady_clock::now();
+
+  bool shouldLog = false;
+  {
+    auto last = lastMissingProxyHashLog_.wlock();
+    if (now >= *last +
+            config_->getEdenConfig()
+                ->missingHgProxyHashLogInterval.getValue()) {
+      shouldLog = true;
+      *last = now;
+    }
+  }
+
+  if (shouldLog) {
+    structuredLogger_->logEvent(MissingProxyHash{});
+  }
+}
+
 void HgQueuedBackingStore::logBackingStoreFetch(
     ObjectFetchContext& context,
     const HgProxyHash& proxyHash,

eden/fs/store/hg/HgQueuedBackingStore.h

@@ -31,6 +31,7 @@ class HgBackingStore;
 class LocalStore;
 class EdenStats;
 class HgImportRequest;
+class StructuredLogger;
 
 constexpr uint8_t kNumberHgQueueWorker = 8;
 
@@ -102,6 +103,7 @@ class HgQueuedBackingStore : public BackingStore {
       std::shared_ptr<EdenStats> stats,
       std::unique_ptr<HgBackingStore> backingStore,
       std::shared_ptr<ReloadableConfig> config,
+      std::shared_ptr<StructuredLogger> structuredLogger,
       std::unique_ptr<BackingStoreLogger> logger,
       uint8_t numberThreads = kNumberHgQueueWorker);
 
@@ -169,6 +171,8 @@ class HgQueuedBackingStore : public BackingStore {
    */
   void processRequest();
 
+  void logMissingProxyHash();
+
   /**
    * Logs a backing store fetch to scuba if the path being fetched is
    * in the configured paths to log. If `identifer` is a RelativePathPiece this
@@ -236,11 +240,18 @@ class HgQueuedBackingStore : public BackingStore {
    */
   std::vector<std::thread> threads_;
 
+  std::shared_ptr<StructuredLogger> structuredLogger_;
+
   /**
    * Logger for backing store imports
    */
   std::unique_ptr<BackingStoreLogger> logger_;
 
+  // The last time we logged a missing proxy hash so the minimum interval is
+  // limited to EdenConfig::missingHgProxyHashLogInterval.
+  folly::Synchronized<std::chrono::steady_clock::time_point>
+      lastMissingProxyHashLog_;
+
   // Track metrics for queued imports
   mutable RequestMetricsScope::LockedRequestWatchList pendingImportBlobWatches_;
   mutable RequestMetricsScope::LockedRequestWatchList pendingImportTreeWatches_;

eden/fs/store/hg/test/HgBackingStoreTest.cpp

@@ -105,6 +105,7 @@ struct HgBackingStoreTest : TestRepo, ::testing::Test {
           stats,
           MetadataImporter::getMetadataImporterFactory<TestMetadataImporter>()),
       nullptr,
+      std::make_shared<NullStructuredLogger>(),
       nullptr)};
   std::shared_ptr<ObjectStore> objectStore{ObjectStore::create(
       localStore,

eden/fs/store/hg/test/HgQueuedBackingStoreTest.cpp

@@ -16,6 +16,7 @@
 #include "eden/fs/store/MemoryLocalStore.h"
 #include "eden/fs/store/hg/HgImporter.h"
 #include "eden/fs/store/hg/HgQueuedBackingStore.h"
+#include "eden/fs/telemetry/NullStructuredLogger.h"
 #include "eden/fs/testharness/HgRepo.h"
 
 // TODO(T80017182) enable these tests in TSAN mode.
@@ -73,6 +74,7 @@ struct HgQueuedBackingStoreTest : TestRepo, ::testing::Test {
         stats,
         std::move(backingStore),
         std::shared_ptr<ReloadableConfig>(),
+        std::make_shared<NullStructuredLogger>(),
         std::make_unique<BackingStoreLogger>(),
         1);
   }

eden/fs/telemetry/LogEvent.h

@@ -72,6 +72,12 @@ struct Fsck {
   }
 };
 
+struct MissingProxyHash {
+  static constexpr const char* type = "missing_proxy_hash";
+
+  void populate(DynamicEvent&) const {}
+};
+
 struct FetchHeavy {
   static constexpr const char* type = "fetch_heavy";