Netplay: Add more logging to save syncing.

Source/Core/Core/NetPlayClient.cpp

@@ -980,6 +980,8 @@ void NetPlayClient::OnSyncSaveData(sf::Packet& packet)
   if (m_local_player->IsHost())
     return;
 
+  INFO_LOG_FMT(NETPLAY, "Processing OnSyncSaveData sub id: {}", static_cast<u8>(sub_id));
+
   switch (sub_id)
   {
   case SyncSaveDataID::Notify:
@@ -1013,6 +1015,8 @@ void NetPlayClient::OnSyncSaveDataNotify(sf::Packet& packet)
   packet >> m_sync_save_data_count;
   m_sync_save_data_success_count = 0;
 
+  INFO_LOG_FMT(NETPLAY, "Initializing wait for {} savegame chunks.", m_sync_save_data_count);
+
   if (m_sync_save_data_count == 0)
     SyncSaveDataResponse(true);
   else
@@ -1026,9 +1030,13 @@ void NetPlayClient::OnSyncSaveDataRaw(sf::Packet& packet)
   int size_override;
   packet >> is_slot_a >> region >> size_override;
 
+  INFO_LOG_FMT(NETPLAY, "Received raw memcard data for slot {}: region {}, size override {}.",
+               is_slot_a ? 'A' : 'B', region, size_override);
+
   // This check is mainly intended to filter out characters which have special meanings in paths
   if (region != JAP_DIR && region != USA_DIR && region != EUR_DIR)
   {
+    WARN_LOG_FMT(NETPLAY, "Received invalid raw memory card region.");
     SyncSaveDataResponse(false);
     return;
   }
@@ -1062,6 +1070,9 @@ void NetPlayClient::OnSyncSaveDataGCI(sf::Packet& packet)
   const std::string path = File::GetUserPath(D_GCUSER_IDX) + GC_MEMCARD_NETPLAY DIR_SEP +
                            fmt::format("Card {}", is_slot_a ? 'A' : 'B');
 
+  INFO_LOG_FMT(NETPLAY, "Received GCI memcard data for slot {}: {}, {} files.",
+               is_slot_a ? 'A' : 'B', path, file_count);
+
   if ((File::Exists(path) && !File::DeleteDirRecursively(path + DIR_SEP)) ||
       !File::CreateFullPath(path + DIR_SEP))
   {
@@ -1075,9 +1086,12 @@ void NetPlayClient::OnSyncSaveDataGCI(sf::Packet& packet)
     std::string file_name;
     packet >> file_name;
 
+    INFO_LOG_FMT(NETPLAY, "Received GCI: {}", file_name);
+
     if (!Common::IsFileNameSafe(file_name) ||
         !DecompressPacketIntoFile(packet, path + DIR_SEP + file_name))
     {
+      WARN_LOG_FMT(NETPLAY, "Received invalid GCI.");
       SyncSaveDataResponse(false);
       return;
     }
@@ -1118,6 +1132,8 @@ void NetPlayClient::OnSyncSaveDataWii(sf::Packet& packet)
   packet >> mii_data;
   if (mii_data)
   {
+    INFO_LOG_FMT(NETPLAY, "Received Mii data.");
+
     auto buffer = DecompressPacketIntoBuffer(packet);
 
     temp_fs->CreateFullPath(IOS::PID_KERNEL, IOS::PID_KERNEL, "/shared2/menu/FaceLib/", 0,
@@ -1136,6 +1152,7 @@ void NetPlayClient::OnSyncSaveDataWii(sf::Packet& packet)
   // Read the saves
   u32 save_count;
   packet >> save_count;
+  INFO_LOG_FMT(NETPLAY, "Received data for {} Wii saves.", save_count);
   for (u32 n = 0; n < save_count; n++)
   {
     u64 title_id = Common::PacketReadU64(packet);
@@ -1147,7 +1164,12 @@ void NetPlayClient::OnSyncSaveDataWii(sf::Packet& packet)
     bool exists;
     packet >> exists;
     if (!exists)
+    {
+      INFO_LOG_FMT(NETPLAY, "No data for Wii save of title {:016x}.", title_id);
       continue;
+    }
+
+    INFO_LOG_FMT(NETPLAY, "Received Wii save of title {:016x}.", title_id);
 
     // Header
     WiiSave::Header header;
@@ -1186,6 +1208,9 @@ void NetPlayClient::OnSyncSaveDataWii(sf::Packet& packet)
       packet >> file.type;
       packet >> file.path;
 
+      INFO_LOG_FMT(NETPLAY, "Received Wii save data of type {} at {}", static_cast<u8>(file.type),
+                   file.path);
+
       if (file.type == WiiSave::Storage::SaveFile::Type::File)
       {
         auto buffer = DecompressPacketIntoBuffer(packet);
@@ -1213,6 +1238,7 @@ void NetPlayClient::OnSyncSaveDataWii(sf::Packet& packet)
   packet >> has_redirected_save;
   if (has_redirected_save)
   {
+    INFO_LOG_FMT(NETPLAY, "Received redirected save.");
     if (!DecompressPacketIntoFolder(packet, redirect_path))
     {
       PanicAlertFmtT("Failed to write redirected save.");
@@ -1230,6 +1256,8 @@ void NetPlayClient::OnSyncSaveDataGBA(sf::Packet& packet)
   u8 slot;
   packet >> slot;
 
+  INFO_LOG_FMT(NETPLAY, "Received GBA save for slot {}.", slot);
+
   const std::string path =
       fmt::format("{}{}{}.sav", File::GetUserPath(D_GBAUSER_IDX), GBA_SAVE_NETPLAY, slot + 1);
   if (File::Exists(path) && !File::Delete(path))

Source/Core/Core/NetPlayServer.cpp

@@ -1667,6 +1667,8 @@ std::optional<SaveSyncInfo> NetPlayServer::CollectSaveSyncInfo()
 // called from ---GUI--- thread
 bool NetPlayServer::SyncSaveData(const SaveSyncInfo& sync_info)
 {
+  INFO_LOG_FMT(NETPLAY, "Sending {} savegame chunks to clients.", sync_info.save_count);
+
   // We're about to sync saves, so set m_saves_synced to false (waits to start game)
   m_saves_synced = false;
 
@@ -1708,12 +1710,16 @@ bool NetPlayServer::SyncSaveData(const SaveSyncInfo& sync_info)
 
       if (File::Exists(path))
       {
+        INFO_LOG_FMT(NETPLAY, "Sending data of raw memcard {} in slot {}.", path,
+                     is_slot_a ? 'A' : 'B');
         if (!CompressFileIntoPacket(path, pac))
           return false;
       }
       else
       {
         // No file, so we'll say the size is 0
+        INFO_LOG_FMT(NETPLAY, "Sending empty marker for raw memcard {} in slot {}.", path,
+                     is_slot_a ? 'A' : 'B');
         pac << sf::Uint64{0};
       }
 
@@ -1736,17 +1742,25 @@ bool NetPlayServer::SyncSaveData(const SaveSyncInfo& sync_info)
         std::vector<std::string> files =
             GCMemcardDirectory::GetFileNamesForGameID(path + DIR_SEP, sync_info.game->GetGameID());
 
+        INFO_LOG_FMT(NETPLAY, "Sending data of GCI memcard {} in slot {} ({} files).", path,
+                     is_slot_a ? 'A' : 'B', files.size());
+
         pac << static_cast<u8>(files.size());
 
         for (const std::string& file : files)
         {
-          pac << file.substr(file.find_last_of('/') + 1);
+          const std::string filename = file.substr(file.find_last_of('/') + 1);
+          INFO_LOG_FMT(NETPLAY, "Sending GCI {}.", filename);
+          pac << filename;
           if (!CompressFileIntoPacket(file, pac))
             return false;
         }
       }
       else
       {
+        INFO_LOG_FMT(NETPLAY, "Sending empty marker for GCI memcard {} in slot {}.", path,
+                     is_slot_a ? 'A' : 'B');
+
         pac << static_cast<u8>(0);
       }
 
@@ -1764,17 +1778,19 @@ bool NetPlayServer::SyncSaveData(const SaveSyncInfo& sync_info)
     // Shove the Mii data into the start the packet
     if (sync_info.mii_data)
     {
+      INFO_LOG_FMT(NETPLAY, "Sending Mii data.");
       pac << true;
-
       if (!CompressBufferIntoPacket(*sync_info.mii_data, pac))
         return false;
     }
     else
     {
+      INFO_LOG_FMT(NETPLAY, "Not sending Mii data.");
       pac << false;  // no mii data
     }
 
     // Carry on with the save files
+    INFO_LOG_FMT(NETPLAY, "Sending {} Wii saves.", sync_info.wii_saves.size());
     pac << static_cast<u32>(sync_info.wii_saves.size());
 
     for (const auto& [title_id, storage] : sync_info.wii_saves)
@@ -1787,8 +1803,12 @@ bool NetPlayServer::SyncSaveData(const SaveSyncInfo& sync_info)
         const std::optional<WiiSave::BkHeader> bk_header = storage->ReadBkHeader();
         const std::optional<std::vector<WiiSave::Storage::SaveFile>> files = storage->ReadFiles();
         if (!header || !bk_header || !files)
+        {
+          INFO_LOG_FMT(NETPLAY, "Wii save of title {:016x} is corrupted.", title_id);
           return false;
+        }
 
+        INFO_LOG_FMT(NETPLAY, "Sending Wii save of title {:016x}.", title_id);
         pac << true;  // save exists
 
         // Header
@@ -1813,6 +1833,9 @@ bool NetPlayServer::SyncSaveData(const SaveSyncInfo& sync_info)
         // Files
         for (const WiiSave::Storage::SaveFile& file : *files)
         {
+          INFO_LOG_FMT(NETPLAY, "Sending Wii save data of type {} at {}",
+                       static_cast<u8>(file.type), file.path);
+
           pac << file.mode << file.attributes << file.type << file.path;
 
           if (file.type == WiiSave::Storage::SaveFile::Type::File)
@@ -1825,18 +1848,22 @@ bool NetPlayServer::SyncSaveData(const SaveSyncInfo& sync_info)
       }
       else
       {
+        INFO_LOG_FMT(NETPLAY, "No data for Wii save of title {:016x}.", title_id);
         pac << false;  // save does not exist
       }
     }
 
     if (sync_info.redirected_save)
     {
+      INFO_LOG_FMT(NETPLAY, "Sending redirected save at {}.",
+                   sync_info.redirected_save->m_target_path);
       pac << true;
       if (!CompressFolderIntoPacket(sync_info.redirected_save->m_target_path, pac))
         return false;
     }
     else
     {
+      INFO_LOG_FMT(NETPLAY, "Not sending redirected save.");
       pac << false;  // no redirected save
     }
 
@@ -1859,12 +1886,14 @@ bool NetPlayServer::SyncSaveData(const SaveSyncInfo& sync_info)
 #endif
       if (File::Exists(path))
       {
+        INFO_LOG_FMT(NETPLAY, "Sending data of GBA save at {} for slot {}.", path, i);
         if (!CompressFileIntoPacket(path, pac))
           return false;
       }
       else
       {
         // No file, so we'll say the size is 0
+        INFO_LOG_FMT(NETPLAY, "Sending empty marker for GBA save at {} for slot {}.", path, i);
         pac << sf::Uint64{0};
       }