Netplay: More logging before game start.

Source/Core/Core/NetPlayClient.cpp

@@ -239,6 +239,8 @@ NetPlayClient::NetPlayClient(const std::string& address, const u16 port, NetPlay
 
 bool NetPlayClient::Connect()
 {
+  INFO_LOG_FMT(NETPLAY, "Connecting to server.");
+
   // send connect message
   sf::Packet packet;
   packet << Common::GetScmRevGitStr();
@@ -541,6 +543,8 @@ void NetPlayClient::OnChunkedDataStart(sf::Packet& packet)
   packet >> title;
   const u64 data_size = Common::PacketReadU64(packet);
 
+  INFO_LOG_FMT(NETPLAY, "Starting data chunk {}.", cid);
+
   m_chunked_data_receive_queue.emplace(cid, sf::Packet{});
 
   std::vector<int> players;
@@ -555,7 +559,12 @@ void NetPlayClient::OnChunkedDataEnd(sf::Packet& packet)
 
   const auto data_packet_iter = m_chunked_data_receive_queue.find(cid);
   if (data_packet_iter == m_chunked_data_receive_queue.end())
+  {
+    INFO_LOG_FMT(NETPLAY, "Invalid data chunk ID {}.", cid);
     return;
+  }
+
+  INFO_LOG_FMT(NETPLAY, "Ending data chunk {}.", cid);
 
   auto& data_packet = data_packet_iter->second;
   OnData(data_packet);
@@ -575,7 +584,10 @@ void NetPlayClient::OnChunkedDataPayload(sf::Packet& packet)
 
   const auto data_packet_iter = m_chunked_data_receive_queue.find(cid);
   if (data_packet_iter == m_chunked_data_receive_queue.end())
+  {
+    INFO_LOG_FMT(NETPLAY, "Invalid data chunk ID {}.", cid);
     return;
+  }
 
   auto& data_packet = data_packet_iter->second;
   while (!packet.endOfPacket())
@@ -585,6 +597,8 @@ void NetPlayClient::OnChunkedDataPayload(sf::Packet& packet)
     data_packet << byte;
   }
 
+  INFO_LOG_FMT(NETPLAY, "Received {} bytes of data chunk {}.", data_packet.getDataSize(), cid);
+
   m_dialog->SetChunkedProgress(m_local_player->pid, data_packet.getDataSize());
 
   sf::Packet progress_packet;
@@ -601,7 +615,12 @@ void NetPlayClient::OnChunkedDataAbort(sf::Packet& packet)
 
   const auto iter = m_chunked_data_receive_queue.find(cid);
   if (iter == m_chunked_data_receive_queue.end())
+  {
+    INFO_LOG_FMT(NETPLAY, "Invalid data chunk ID {}.", cid);
     return;
+  }
+
+  INFO_LOG_FMT(NETPLAY, "Aborting data chunk {}.", cid);
 
   m_chunked_data_receive_queue.erase(iter);
   m_dialog->HideChunkedProgressDialog();
@@ -1284,6 +1303,8 @@ void NetPlayClient::OnSyncCodes(sf::Packet& packet)
   SyncCodeID sub_id;
   packet >> sub_id;
 
+  INFO_LOG_FMT(NETPLAY, "Processing OnSyncCodes sub id: {}", static_cast<u8>(sub_id));
+
   // Check Which Operation to Perform with This Packet
   switch (sub_id)
   {
@@ -1331,7 +1352,7 @@ void NetPlayClient::OnSyncCodesNotifyGecko(sf::Packet& packet)
 
   m_sync_gecko_codes_success_count = 0;
 
-  NOTICE_LOG_FMT(ACTIONREPLAY, "Receiving {} Gecko codelines", m_sync_gecko_codes_count);
+  INFO_LOG_FMT(NETPLAY, "Receiving {} Gecko codelines", m_sync_gecko_codes_count);
 
   // Check if no codes to sync, if so return as finished
   if (m_sync_gecko_codes_count == 0)
@@ -1365,7 +1386,7 @@ void NetPlayClient::OnSyncCodesDataGecko(sf::Packet& packet)
     packet >> new_code.address;
     packet >> new_code.data;
 
-    NOTICE_LOG_FMT(ACTIONREPLAY, "Received {:08x} {:08x}", new_code.address, new_code.data);
+    INFO_LOG_FMT(NETPLAY, "Received {:08x} {:08x}", new_code.address, new_code.data);
 
     gcode.codes.push_back(std::move(new_code));
 
@@ -1398,7 +1419,7 @@ void NetPlayClient::OnSyncCodesNotifyAR(sf::Packet& packet)
 
   m_sync_ar_codes_success_count = 0;
 
-  NOTICE_LOG_FMT(ACTIONREPLAY, "Receiving {} AR codelines", m_sync_ar_codes_count);
+  INFO_LOG_FMT(NETPLAY, "Receiving {} AR codelines", m_sync_ar_codes_count);
 
   // Check if no codes to sync, if so return as finished
   if (m_sync_ar_codes_count == 0)
@@ -1432,7 +1453,7 @@ void NetPlayClient::OnSyncCodesDataAR(sf::Packet& packet)
     packet >> new_code.cmd_addr;
     packet >> new_code.value;
 
-    NOTICE_LOG_FMT(ACTIONREPLAY, "Received {:08x} {:08x}", new_code.cmd_addr, new_code.value);
+    INFO_LOG_FMT(NETPLAY, "Received {:08x} {:08x}", new_code.cmd_addr, new_code.value);
     arcode.ops.push_back(new_code);
 
     if (++m_sync_ar_codes_success_count >= m_sync_ar_codes_count)

Source/Core/Core/NetPlayServer.cpp

@@ -239,6 +239,8 @@ void NetPlayServer::SetupIndex()
 // called from ---NETPLAY--- thread
 void NetPlayServer::ThreadFunc()
 {
+  INFO_LOG_FMT(NETPLAY, "NetPlayServer starting.");
+
   while (m_do_loop)
   {
     // update pings every so many seconds
@@ -305,12 +307,17 @@ void NetPlayServer::ThreadFunc()
           // uninitialized client, we'll assume this is their initialization packet
           ConnectionError error;
           {
+            INFO_LOG_FMT(NETPLAY, "Initializing peer {:x}:{}", netEvent.peer->address.host,
+                         netEvent.peer->address.port);
             std::lock_guard lkg(m_crit.game);
             error = OnConnect(netEvent.peer, rpac);
           }
 
           if (error != ConnectionError::NoError)
           {
+            INFO_LOG_FMT(NETPLAY, "Error {} initializing peer {:x}:{}", u8(error),
+                         netEvent.peer->address.host, netEvent.peer->address.port);
+
             sf::Packet spac;
             spac << error;
             // don't need to lock, this client isn't in the client map
@@ -326,6 +333,8 @@ void NetPlayServer::ThreadFunc()
           Client& client = it->second;
           if (OnData(rpac, client) != 0)
           {
+            INFO_LOG_FMT(NETPLAY, "Invalid packet from client {}, disconnecting.", client.pid);
+
             // if a bad packet is received, disconnect the client
             std::lock_guard lkg(m_crit.game);
             OnDisconnect(client);
@@ -345,6 +354,7 @@ void NetPlayServer::ThreadFunc()
         if (it != m_players.end())
         {
           Client& client = it->second;
+          INFO_LOG_FMT(NETPLAY, "Disconnecting client {}.", client.pid);
           OnDisconnect(client);
 
           ClearPeerPlayerId(netEvent.peer);
@@ -357,6 +367,8 @@ void NetPlayServer::ThreadFunc()
     }
   }
 
+  INFO_LOG_FMT(NETPLAY, "NetPlayServer shutting down.");
+
   // close listening socket and client sockets
   for (auto& player_entry : m_players)
   {
@@ -699,7 +711,8 @@ unsigned int NetPlayServer::OnData(sf::Packet& packet, Client& player)
   MessageID mid;
   packet >> mid;
 
-  INFO_LOG_FMT(NETPLAY, "Got client message: {:x}", static_cast<u8>(mid));
+  INFO_LOG_FMT(NETPLAY, "Got client message: {:x} from client {}", static_cast<u8>(mid),
+               player.pid);
 
   // don't need lock because this is the only thread that modifies the players
   // only need locks for writes to m_players in this thread
@@ -1084,6 +1097,9 @@ unsigned int NetPlayServer::OnData(sf::Packet& packet, Client& player)
     SyncSaveDataID sub_id;
     packet >> sub_id;
 
+    INFO_LOG_FMT(NETPLAY, "Got client SyncSaveData message: {:x} from client {}", u8(sub_id),
+                 player.pid);
+
     switch (sub_id)
     {
     case SyncSaveDataID::Success:
@@ -1093,12 +1109,23 @@ unsigned int NetPlayServer::OnData(sf::Packet& packet, Client& player)
         m_save_data_synced_players++;
         if (m_save_data_synced_players >= m_players.size() - 1)
         {
+          INFO_LOG_FMT(NETPLAY, "SyncSaveData: All players synchronized. ({} >= {})",
+                       m_save_data_synced_players, m_players.size() - 1);
           m_dialog->AppendChat(Common::GetStringT("All players' saves synchronized."));
 
           // Saves are synced, check if codes are as well and attempt to start the game
           m_saves_synced = true;
           CheckSyncAndStartGame();
         }
+        else
+        {
+          INFO_LOG_FMT(NETPLAY, "SyncSaveData: Not all players synchronized. ({} < {})",
+                       m_save_data_synced_players, m_players.size() - 1);
+        }
+      }
+      else
+      {
+        INFO_LOG_FMT(NETPLAY, "SyncSaveData: Start not pending.");
       }
     }
     break;
@@ -1127,6 +1154,9 @@ unsigned int NetPlayServer::OnData(sf::Packet& packet, Client& player)
     SyncCodeID sub_id;
     packet >> sub_id;
 
+    INFO_LOG_FMT(NETPLAY, "Got client SyncCodes message: {:x} from client {}", u8(sub_id),
+                 player.pid);
+
     // Check If Code Sync was successful or not
     switch (sub_id)
     {
@@ -1136,12 +1166,24 @@ unsigned int NetPlayServer::OnData(sf::Packet& packet, Client& player)
       {
         if (++m_codes_synced_players >= m_players.size() - 1)
         {
+          INFO_LOG_FMT(NETPLAY, "SyncCodes: All players synchronized. ({} >= {})",
+                       m_codes_synced_players, m_players.size() - 1);
+
           m_dialog->AppendChat(Common::GetStringT("All players' codes synchronized."));
 
           // Codes are synced, check if saves are as well and attempt to start the game
           m_codes_synced = true;
           CheckSyncAndStartGame();
         }
+        else
+        {
+          INFO_LOG_FMT(NETPLAY, "SyncCodes: Not all players synchronized. ({} < {})",
+                       m_codes_synced_players, m_players.size() - 1);
+        }
+      }
+      else
+      {
+        INFO_LOG_FMT(NETPLAY, "SyncCodes: Start not pending.");
       }
     }
     break;
@@ -1206,6 +1248,9 @@ bool NetPlayServer::ChangeGame(const SyncIdentifier& sync_identifier,
 {
   std::lock_guard lkg(m_crit.game);
 
+  INFO_LOG_FMT(NETPLAY, "Changing game to {} ({:02x}).", netplay_name,
+               fmt::join(sync_identifier.sync_hash, ""));
+
   m_selected_game_identifier = sync_identifier;
   m_selected_game_name = netplay_name;
 
@@ -1248,10 +1293,15 @@ bool NetPlayServer::SetupNetSettings()
   const auto game = m_dialog->FindGameFile(m_selected_game_identifier);
   if (game == nullptr)
   {
+    ERROR_LOG_FMT(NETPLAY, "Game {:02x} not found in game list.",
+                  fmt::join(m_selected_game_identifier.sync_hash, ""));
     PanicAlertFmtT("Selected game doesn't exist in game list!");
     return false;
   }
 
+  INFO_LOG_FMT(NETPLAY, "Loading game settings for {:02x}.",
+               fmt::join(m_selected_game_identifier.sync_hash, ""));
+
   NetPlay::NetSettings settings;
 
   // Load GameINI so we can sync the settings from it
@@ -1395,6 +1445,8 @@ struct SaveSyncInfo
 // called from ---GUI--- thread
 bool NetPlayServer::RequestStartGame()
 {
+  INFO_LOG_FMT(NETPLAY, "Start Game requested.");
+
   if (!SetupNetSettings())
     return false;
 
@@ -1452,12 +1504,15 @@ bool NetPlayServer::RequestStartGame()
     return StartGame();
   }
 
+  INFO_LOG_FMT(NETPLAY, "Waiting for data sync with clients.");
   return true;
 }
 
 // called from multiple threads
 bool NetPlayServer::StartGame()
 {
+  INFO_LOG_FMT(NETPLAY, "Starting game.");
+
   m_timebase_by_frame.clear();
   m_desync_detected = false;
   std::lock_guard lkg(m_crit.game);
@@ -1577,24 +1632,36 @@ void NetPlayServer::AbortGameStart()
 {
   if (m_start_pending)
   {
+    INFO_LOG_FMT(NETPLAY, "Aborting game start.");
     m_dialog->OnGameStartAborted();
     ChunkedDataAbort();
     m_start_pending = false;
   }
+  else
+  {
+    INFO_LOG_FMT(NETPLAY, "Aborting game start but no game start pending.");
+  }
 }
 
 // called from ---GUI--- thread
 std::optional<SaveSyncInfo> NetPlayServer::CollectSaveSyncInfo()
 {
+  INFO_LOG_FMT(NETPLAY, "Collecting saves.");
+
   SaveSyncInfo sync_info;
 
   sync_info.save_count = 0;
   for (ExpansionInterface::Slot slot : ExpansionInterface::MEMCARD_SLOTS)
   {
-    if (m_settings.exi_device[slot] == ExpansionInterface::EXIDeviceType::MemoryCard ||
+    if (m_settings.exi_device[slot] == ExpansionInterface::EXIDeviceType::MemoryCard)
-        Config::Get(Config::GetInfoForEXIDevice(slot)) ==
-            ExpansionInterface::EXIDeviceType::MemoryCardFolder)
     {
+      INFO_LOG_FMT(NETPLAY, "Adding memory card (raw) in slot {}.", slot);
+      ++sync_info.save_count;
+    }
+    else if (Config::Get(Config::GetInfoForEXIDevice(slot)) ==
+             ExpansionInterface::EXIDeviceType::MemoryCardFolder)
+    {
+      INFO_LOG_FMT(NETPLAY, "Adding memory card (folder) in slot {}.", slot);
       ++sync_info.save_count;
     }
   }
@@ -1611,6 +1678,8 @@ std::optional<SaveSyncInfo> NetPlayServer::CollectSaveSyncInfo()
                                    sync_info.game->GetPlatform() == DiscIO::Platform::WiiWAD ||
                                    sync_info.game->GetPlatform() == DiscIO::Platform::ELFOrDOL))
   {
+    INFO_LOG_FMT(NETPLAY, "Adding Wii saves.");
+
     sync_info.has_wii_save = true;
     ++sync_info.save_count;
 
@@ -1655,10 +1724,14 @@ std::optional<SaveSyncInfo> NetPlayServer::CollectSaveSyncInfo()
     }
   }
 
-  for (const auto& config : m_gba_config)
+  for (size_t i = 0; i < m_gba_config.size(); ++i)
   {
+    const auto& config = m_gba_config[i];
     if (config.enabled && config.has_rom)
+    {
+      INFO_LOG_FMT(NETPLAY, "Adding GBA save in slot {}.", i);
       ++sync_info.save_count;
+    }
   }
 
   return sync_info;
@@ -1907,6 +1980,8 @@ bool NetPlayServer::SyncSaveData(const SaveSyncInfo& sync_info)
 
 bool NetPlayServer::SyncCodes()
 {
+  INFO_LOG_FMT(NETPLAY, "Sending codes to clients.");
+
   // Sync Codes is ticked, so set m_codes_synced to false
   m_codes_synced = false;
 
@@ -1948,16 +2023,16 @@ bool NetPlayServer::SyncCodes()
     u16 codelines = 0;
     for (const Gecko::GeckoCode& active_code : s_active_codes)
     {
-      NOTICE_LOG_FMT(ACTIONREPLAY, "Indexing {}", active_code.name);
+      INFO_LOG_FMT(NETPLAY, "Indexing {}", active_code.name);
       for (const Gecko::GeckoCode::Code& code : active_code.codes)
       {
-        NOTICE_LOG_FMT(ACTIONREPLAY, "{:08x} {:08x}", code.address, code.data);
+        INFO_LOG_FMT(NETPLAY, "{:08x} {:08x}", code.address, code.data);
         codelines++;
       }
     }
 
     // Output codelines to send
-    NOTICE_LOG_FMT(ACTIONREPLAY, "Sending {} Gecko codelines", codelines);
+    INFO_LOG_FMT(NETPLAY, "Sending {} Gecko codelines", codelines);
 
     // Send initial packet. Notify of the sync operation and total number of lines being sent.
     {
@@ -1976,10 +2051,10 @@ bool NetPlayServer::SyncCodes()
       // Iterate through the active code vector and send each codeline
       for (const Gecko::GeckoCode& active_code : s_active_codes)
       {
-        NOTICE_LOG_FMT(ACTIONREPLAY, "Sending {}", active_code.name);
+        INFO_LOG_FMT(NETPLAY, "Sending {}", active_code.name);
         for (const Gecko::GeckoCode::Code& code : active_code.codes)
         {
-          NOTICE_LOG_FMT(ACTIONREPLAY, "{:08x} {:08x}", code.address, code.data);
+          INFO_LOG_FMT(NETPLAY, "{:08x} {:08x}", code.address, code.data);
           pac << code.address;
           pac << code.data;
         }
@@ -1998,16 +2073,16 @@ bool NetPlayServer::SyncCodes()
     u16 codelines = 0;
     for (const ActionReplay::ARCode& active_code : s_active_codes)
     {
-      NOTICE_LOG_FMT(ACTIONREPLAY, "Indexing {}", active_code.name);
+      INFO_LOG_FMT(NETPLAY, "Indexing {}", active_code.name);
       for (const ActionReplay::AREntry& op : active_code.ops)
       {
-        NOTICE_LOG_FMT(ACTIONREPLAY, "{:08x} {:08x}", op.cmd_addr, op.value);
+        INFO_LOG_FMT(NETPLAY, "{:08x} {:08x}", op.cmd_addr, op.value);
         codelines++;
       }
     }
 
     // Output codelines to send
-    NOTICE_LOG_FMT(ACTIONREPLAY, "Sending {} AR codelines", codelines);
+    INFO_LOG_FMT(NETPLAY, "Sending {} AR codelines", codelines);
 
     // Send initial packet. Notify of the sync operation and total number of lines being sent.
     {
@@ -2026,10 +2101,10 @@ bool NetPlayServer::SyncCodes()
       // Iterate through the active code vector and send each codeline
       for (const ActionReplay::ARCode& active_code : s_active_codes)
       {
-        NOTICE_LOG_FMT(ACTIONREPLAY, "Sending {}", active_code.name);
+        INFO_LOG_FMT(NETPLAY, "Sending {}", active_code.name);
         for (const ActionReplay::AREntry& op : active_code.ops)
         {
-          NOTICE_LOG_FMT(ACTIONREPLAY, "{:08x} {:08x}", op.cmd_addr, op.value);
+          INFO_LOG_FMT(NETPLAY, "{:08x} {:08x}", op.cmd_addr, op.value);
           pac << op.cmd_addr;
           pac << op.value;
         }
@@ -2045,8 +2120,13 @@ void NetPlayServer::CheckSyncAndStartGame()
 {
   if (m_saves_synced && m_codes_synced)
   {
+    INFO_LOG_FMT(NETPLAY, "Synchronized, starting game.");
     StartGame();
   }
+  else
+  {
+    INFO_LOG_FMT(NETPLAY, "Not synchronized.");
+  }
 }
 
 u64 NetPlayServer::GetInitialNetPlayRTC() const
@@ -2218,6 +2298,8 @@ std::vector<std::pair<std::string, std::string>> NetPlayServer::GetInterfaceList
 // called from ---Chunked Data--- thread
 void NetPlayServer::ChunkedDataThreadFunc()
 {
+  INFO_LOG_FMT(NETPLAY, "Starting Chunked Data Thread.");
+
   while (m_do_loop)
   {
     m_chunked_data_event.Wait();
@@ -2258,6 +2340,9 @@ void NetPlayServer::ChunkedDataThreadFunc()
         }
         player_count = players.size();
 
+        INFO_LOG_FMT(NETPLAY, "Informing players {} of data chunk {} start.",
+                     fmt::join(players, ", "), id);
+
         sf::Packet pac;
         pac << MessageID::ChunkedDataStart;
         pac << id << e.title << sf::Uint64{e.packet.getDataSize()};
@@ -2280,6 +2365,8 @@ void NetPlayServer::ChunkedDataThreadFunc()
           return;
         if (m_abort_chunked_data)
         {
+          INFO_LOG_FMT(NETPLAY, "Informing players of data chunk {} abort.", id);
+
           sf::Packet pac;
           pac << MessageID::ChunkedDataAbort;
           pac << id;
@@ -2303,6 +2390,9 @@ void NetPlayServer::ChunkedDataThreadFunc()
         size_t len = std::min(CHUNKED_DATA_UNIT_SIZE, e.packet.getDataSize() - index);
         pac.append(static_cast<const u8*>(e.packet.getData()) + index, len);
 
+        INFO_LOG_FMT(NETPLAY, "Sending data chunk of {} ({} bytes at {}/{}).", id, len, index,
+                     e.packet.getDataSize());
+
         ChunkedDataSend(std::move(pac), e.target_pid, e.target_mode);
         index += CHUNKED_DATA_UNIT_SIZE;
 
@@ -2315,6 +2405,8 @@ void NetPlayServer::ChunkedDataThreadFunc()
 
       if (!m_abort_chunked_data)
       {
+        INFO_LOG_FMT(NETPLAY, "Informing players of data chunk {} end.", id);
+
         sf::Packet pac;
         pac << MessageID::ChunkedDataEnd;
         pac << id;
@@ -2330,6 +2422,8 @@ void NetPlayServer::ChunkedDataThreadFunc()
       m_chunked_data_queue.Pop();
     }
   }
+
+  INFO_LOG_FMT(NETPLAY, "Stopping Chunked Data Thread.");
 }
 
 // called from ---Chunked Data--- thread