issue-1751: [Filestore] Introduce logging to TWriteBackCache (#4558)

Author: e673

cloud/filestore/libs/diagnostics/critical_events.h

@@ -35,6 +35,7 @@ namespace NCloud::NFileStore{
     xxx(RenameNodeRequestForLocalNode)                                         \
     xxx(InvalidShardNo)                                                        \
     xxx(WriteBackCacheCreatingOrDeletingError)                                 \
+    xxx(WriteBackCacheCorruptionError)                                         \
     xxx(ErrorWasSentToTheGuest)                                                \
     xxx(DirectoryHandlesStorageError)                                          \
 // FILESTORE_CRITICAL_EVENTS

cloud/filestore/libs/vfs_fuse/loop.cpp

@@ -969,8 +969,12 @@ class TFileSystemLoop final
                         HandleOpsQueueFileLock);
 
                     if (HasError(error)) {
-                        ReportHandleOpsQueueCreatingOrDeletingError(
-                            error.GetMessage());
+                        ReportHandleOpsQueueCreatingOrDeletingError(Sprintf(
+                            "[f:%s][c:%s] CreateAndLockFile error: %s (%s)",
+                            Config->GetFileSystemId().Quote().c_str(),
+                            Config->GetClientId().Quote().c_str(),
+                            error.GetMessage().c_str(),
+                            path.c_str()));
                         return error;
                     }
 
@@ -979,14 +983,11 @@ class TFileSystemLoop final
                         Config->GetHandleOpsQueueSize());
                     HandleOpsQueueInitialized = true;
                 } else {
-                    TString msg = "Error initializing HandleOpsQueue: "
-                        "HandleOpsQueuePath is not set";
-                    STORAGE_WARN("[f:%s][c:%s] %s",
+                    ReportHandleOpsQueueCreatingOrDeletingError(Sprintf(
+                        "[f:%s][c:%s] Error initializing HandleOpsQueue: "
+                        "HandleOpsQueuePath is not set",
                         Config->GetFileSystemId().Quote().c_str(),
-                        Config->GetClientId().Quote().c_str(),
-                        msg.c_str()
-                    );
-                    ReportHandleOpsQueueCreatingOrDeletingError(msg);
+                        Config->GetClientId().Quote().c_str()));
                 }
             }
 
@@ -1003,8 +1004,12 @@ class TFileSystemLoop final
                         WriteBackCacheFileLock);
 
                     if (HasError(error)) {
-                        ReportWriteBackCacheCreatingOrDeletingError(
-                            error.GetMessage());
+                        ReportWriteBackCacheCreatingOrDeletingError(Sprintf(
+                            "[f:%s][c:%s] CreateAndLockFile error: %s (%s)",
+                            Config->GetFileSystemId().Quote().c_str(),
+                            Config->GetClientId().Quote().c_str(),
+                            error.GetMessage().c_str(),
+                            path.c_str()));
                         return error;
                     }
 
@@ -1013,6 +1018,9 @@ class TFileSystemLoop final
                         Scheduler,
                         Timer,
                         CreateDummyWriteBackCacheStats(),
+                        Log,
+                        Config->GetFileSystemId(),
+                        Config->GetClientId(),
                         path / WriteBackCacheFileName,
                         Config->GetWriteBackCacheCapacity(),
                         Config->GetWriteBackCacheAutomaticFlushPeriod(),
@@ -1023,15 +1031,11 @@ class TFileSystemLoop final
                     );
                     WriteBackCacheInitialized = true;
                 } else {
-                    TString msg =
-                        "Error initializing WriteBackCache: "
-                        "WriteBackCachePath is not set";
-                    STORAGE_WARN(
-                        "[f:%s][c:%s] %s",
+                    ReportWriteBackCacheCreatingOrDeletingError(Sprintf(
+                        "[f:%s][c:%s] Error initializing WriteBackCache: "
+                        "WriteBackCachePath is not set",
                         Config->GetFileSystemId().Quote().c_str(),
-                        Config->GetClientId().Quote().c_str(),
-                        msg.c_str());
-                    ReportWriteBackCacheCreatingOrDeletingError(msg);
+                        Config->GetClientId().Quote().c_str()));
                 }
             }
 

cloud/filestore/libs/vfs_fuse/write_back_cache/write_back_cache.cpp

@@ -2,10 +2,12 @@
 
 #include "read_write_range_lock.h"
 
+#include <cloud/filestore/libs/diagnostics/critical_events.h>
 #include <cloud/filestore/libs/service/context.h>
 
 #include <cloud/storage/core/libs/common/file_ring_buffer.h>
 
+#include <library/cpp/digest/crc32c/crc32c.h>
 #include <library/cpp/threading/future/subscription/wait_all.h>
 
 #include <util/generic/hash_set.h>
@@ -292,6 +294,8 @@ class TWriteBackCache::TImpl final
     const ITimerPtr Timer;
     const IWriteBackCacheStatsPtr Stats;
     const TFlushConfig FlushConfig;
+    const TLog Log;
+    const TString LogTag;
 
     // All fields below should be protected by this lock
     TMutex Lock;
@@ -329,6 +333,9 @@ class TWriteBackCache::TImpl final
             ISchedulerPtr scheduler,
             ITimerPtr timer,
             IWriteBackCacheStatsPtr stats,
+            TLog log,
+            const TString& fileSystemId,
+            const TString& clientId,
             const TString& filePath,
             ui64 capacityBytes,
             TFlushConfig flushConfig)
@@ -337,6 +344,9 @@ class TWriteBackCache::TImpl final
         , Timer(std::move(timer))
         , Stats(std::move(stats))
         , FlushConfig(flushConfig)
+        , Log(std::move(log))
+        , LogTag(
+            Sprintf("[f:%s][c:%s]", fileSystemId.c_str(), clientId.c_str()))
         , CachedEntriesPersistentQueue(filePath, capacityBytes)
     {
         // File ring buffer should be able to store any valid TWriteDataRequest.
@@ -349,27 +359,58 @@ class TWriteBackCache::TImpl final
 
         Stats->ResetNonDerivativeCounters();
 
+        TWriteDataEntryDeserializationStats deserializationStats;
+
         CachedEntriesPersistentQueue.Visit(
             [&](auto checksum, auto serializedRequest)
             {
                 auto entry = std::make_unique<TWriteDataEntry>(
                     checksum,
                     serializedRequest,
+                    deserializationStats,
                     this);
 
                 if (entry->IsCorrupted()) {
                     // This may happen when a buffer was corrupted.
                     // We should add this entry to a queue like a normal entry
                     // because there is 1-by-1 correspondence between
                     // CachedEntriesPersistentQueue and CachedEntries.
-                    // TODO(nasonov): report it
                     CachedEntries.push_back(std::move(entry));
                 } else {
                     auto* nodeState = GetOrCreateNodeState(entry->GetNodeId());
                     AddCachedEntry(nodeState, std::move(entry));
                 }
             });
 
+        STORAGE_INFO(
+            LogTag << " WriteBackCache has been initialized "
+            << "{\"FilePath\": " << filePath.Quote()
+            << ", \"RawCapacityBytes\": "
+            << CachedEntriesPersistentQueue.GetRawCapacity()
+            << ", \"RawUsedBytesCount\": "
+            << CachedEntriesPersistentQueue.GetRawUsedBytesCount()
+            << ", \"WriteDataRequestCount\": "
+            << CachedEntriesPersistentQueue.Size() << "}");
+
+        if (deserializationStats.HasFailed()) {
+            // Each deserialization failure event has been already reported
+            // as a critical error - just write statistics to the log
+            STORAGE_ERROR(
+                LogTag << " WriteBackCache request deserialization failure "
+                << "{\"ChecksumMismatchCount\": "
+                << deserializationStats.ChecksumMismatchCount
+                << ", \"EntrySizeMismatchCount\": "
+                << deserializationStats.EntrySizeMismatchCount
+                << ", \"ProtobufDeserializationErrorCount\": "
+                << deserializationStats.ProtobufDeserializationErrorCount
+                << "}");
+        }
+
+        if (CachedEntriesPersistentQueue.IsCorrupted()) {
+            ReportWriteBackCacheCorruptionError(
+                LogTag + " WriteBackCache persistent queue is corrupted");
+        }
+
         UpdatePersistentQueueStats();
     }
 
@@ -1044,8 +1085,18 @@ class TWriteBackCache::TImpl final
                 FlushConfig.MaxSumWriteRequestsSize);
 
             if (entryCount == 0) {
-                // Even a single entry is too large to flush
-                // TODO(nasonov): report and try to flush it anyway
+                STORAGE_WARN(
+                    LogTag << " WriteBackCache WriteData request size exceeds "
+                    "flush limits, flushing anyway "
+                    << "{\"MaxWriteRequestSize\": "
+                    << FlushConfig.MaxWriteRequestSize
+                    << ", \"MaxWriteRequestsCount\": "
+                    << FlushConfig.MaxWriteRequestsCount
+                    << ", \"MaxSumWriteRequestsSize\": "
+                    << FlushConfig.MaxSumWriteRequestsSize
+                    << ", \"WriteDataRequestSize\": "
+                    << nodeState->CachedEntries.front()->GetBuffer().size()
+                    << "}");
                 entryCount = 1;
             }
 
@@ -1256,6 +1307,9 @@ TWriteBackCache::TWriteBackCache(
         ISchedulerPtr scheduler,
         ITimerPtr timer,
         IWriteBackCacheStatsPtr stats,
+        TLog log,
+        const TString& fileSystemId,
+        const TString& clientId,
         const TString& filePath,
         ui64 capacityBytes,
         TDuration automaticFlushPeriod,
@@ -1269,6 +1323,9 @@ TWriteBackCache::TWriteBackCache(
             std::move(scheduler),
             std::move(timer),
             std::move(stats),
+            std::move(log),
+            fileSystemId,
+            clientId,
             filePath,
             capacityBytes,
             {.AutomaticFlushPeriod = automaticFlushPeriod,
@@ -1321,10 +1378,24 @@ TWriteBackCache::TWriteDataEntry::TWriteDataEntry(
 TWriteBackCache::TWriteDataEntry::TWriteDataEntry(
     ui32 checksum,
     TStringBuf serializedRequest,
+    TWriteDataEntryDeserializationStats& deserializationStats,
     TImpl* impl)
 {
-    // TODO(nasonov): validate checksum
+    deserializationStats.EntryCount++;
+
     Y_UNUSED(checksum);
+    // TODO(nasonov): validate checksum when TFileRingBuffer supports
+    // in-place allocation. Currently, data is written directly to the
+    // TFileRingBuffer without Crc32 calculation
+    //
+    // auto expectedChecksum =
+    //    Crc32c(serializedRequest.data(), serializedRequest.size());
+    //
+    // if (expectedChecksum != checksum) {
+    //    stats.ChecksumMismatchCount++;
+    //    SetStatus(EWriteDataRequestStatus::Corrupted, impl);
+    //    return;
+    //}
 
     TMemoryInput mi(serializedRequest);
 
@@ -1336,23 +1407,29 @@ TWriteBackCache::TWriteDataEntry::TWriteDataEntry(
         // Currently this may happen when execution stopped between allocation
         // and Serialization. In future, this can happen only as a result of
         // corruption
+        deserializationStats.EntrySizeMismatchCount++;
+        ReportWriteBackCacheCorruptionError(
+            "TWriteDataEntry deserialization error: entry is empty");
         SetStatus(EWriteDataRequestStatus::Corrupted, impl);
         return;
     }
 
     const char* bufferPtr = mi.Buf();
 
     if (mi.Skip(bufferSize) != bufferSize) {
-        // Buffer corruption
-        // TODO(nasonov): report and handle
+        deserializationStats.EntrySizeMismatchCount++;
+        ReportWriteBackCacheCorruptionError(
+            "TWriteDataEntry deserialization error: invalid entry size");
         SetStatus(EWriteDataRequestStatus::Corrupted, impl);
         return;
     }
 
     auto parsedRequest = std::make_shared<NProto::TWriteDataRequest>();
-    if (!parsedRequest->ParseFromArray(mi.Buf(), static_cast<int>(mi.Avail()))) {
-        // Buffer corruption
-        // TODO(nasonov): report and handle
+    if (!parsedRequest->ParseFromArray(mi.Buf(), static_cast<int>(mi.Avail())))
+    {
+        deserializationStats.ProtobufDeserializationErrorCount++;
+        ReportWriteBackCacheCorruptionError(
+            "TWriteDataEntry deserialization error: ParseFromArray has failed");
         SetStatus(EWriteDataRequestStatus::Corrupted, impl);
         return;
     }

cloud/filestore/libs/vfs_fuse/write_back_cache/write_back_cache.h

@@ -5,6 +5,7 @@
 
 #include <cloud/storage/core/libs/common/scheduler.h>
 #include <cloud/storage/core/libs/common/timer.h>
+#include <cloud/storage/core/libs/diagnostics/logging.h>
 
 #include <library/cpp/threading/future/future.h>
 
@@ -33,6 +34,9 @@ class TWriteBackCache final
         ISchedulerPtr scheduler,
         ITimerPtr timer,
         IWriteBackCacheStatsPtr stats,
+        TLog log,
+        const TString& fileSystemId,
+        const TString& clientId,
         const TString& filePath,
         ui64 capacityBytes,
         TDuration automaticFlushPeriod,
@@ -68,6 +72,7 @@ class TWriteBackCache final
     friend struct TCalculateDataPartsToReadTestBootstrap;
 
     class TWriteDataEntry;
+    struct TWriteDataEntryDeserializationStats;
     struct TWriteDataEntryPart;
     struct TNodeState;
     struct TFlushState;

cloud/filestore/libs/vfs_fuse/write_back_cache/write_back_cache_impl.h

@@ -16,6 +16,22 @@ namespace NCloud::NFileStore::NFuse {
 
 ////////////////////////////////////////////////////////////////////////////////
 
+struct TWriteBackCache::TWriteDataEntryDeserializationStats
+{
+    ui64 EntryCount = 0;
+    ui64 ChecksumMismatchCount = 0;
+    ui64 EntrySizeMismatchCount = 0;
+    ui64 ProtobufDeserializationErrorCount = 0;
+
+    bool HasFailed() const
+    {
+        return ChecksumMismatchCount > 0 || EntrySizeMismatchCount > 0 ||
+               ProtobufDeserializationErrorCount > 0;
+    }
+};
+
+////////////////////////////////////////////////////////////////////////////////
+
 class TWriteBackCache::TWriteDataEntry
     : public TIntrusiveListItem<TWriteDataEntry>
 {
@@ -46,6 +62,7 @@ class TWriteBackCache::TWriteDataEntry
     TWriteDataEntry(
         ui32 checksum,
         TStringBuf serializedRequest,
+        TWriteDataEntryDeserializationStats& stats,
         TImpl* impl);
 
     const NProto::TWriteDataRequest* GetRequest() const

cloud/filestore/libs/vfs_fuse/write_back_cache/write_back_cache_ut.cpp

@@ -487,6 +487,9 @@ struct TBootstrap
             Scheduler,
             Timer,
             Stats,
+            Log,
+            "FileSystemId",
+            "ClientId",
             TempFileHandle.GetName(),
             CacheCapacityBytes,
             CacheAutomaticFlushPeriod,