Merge pull request #11704 from AdmiralCurtiss/more-log

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)
@@ -1560,6 +1581,8 @@ void NetPlayClient::SendAsync(sf::Packet&& packet, const u8 channel_id)
 // called from ---NETPLAY--- thread
 void NetPlayClient::ThreadFunc()
 {
+  INFO_LOG_FMT(NETPLAY, "NetPlayClient starting.");
+
   Common::QoSSession qos_session;
   if (Config::Get(Config::NETPLAY_ENABLE_QOS))
   {
@@ -1585,10 +1608,12 @@ void NetPlayClient::ThreadFunc()
     net = enet_host_service(m_client, &netEvent, 250);
     while (!m_async_queue.Empty())
     {
+      INFO_LOG_FMT(NETPLAY, "Processing async queue event.");
       {
         auto& e = m_async_queue.Front();
         Send(e.packet, e.channel_id);
       }
+      INFO_LOG_FMT(NETPLAY, "Processing async queue event done.");
       m_async_queue.Pop();
     }
     if (net > 0)
@@ -1596,13 +1621,20 @@ void NetPlayClient::ThreadFunc()
       sf::Packet rpac;
       switch (netEvent.type)
       {
+      case ENET_EVENT_TYPE_CONNECT:
+        INFO_LOG_FMT(NETPLAY, "enet_host_service: connect event");
+        break;
       case ENET_EVENT_TYPE_RECEIVE:
+        INFO_LOG_FMT(NETPLAY, "enet_host_service: receive event");
+
         rpac.append(netEvent.packet->data, netEvent.packet->dataLength);
         OnData(rpac);
 
         enet_packet_destroy(netEvent.packet);
         break;
       case ENET_EVENT_TYPE_DISCONNECT:
+        INFO_LOG_FMT(NETPLAY, "enet_host_service: disconnect event");
+
         m_dialog->OnConnectionLost();
 
         if (m_is_running.IsSet())
@@ -1610,11 +1642,22 @@ void NetPlayClient::ThreadFunc()
 
         break;
       default:
+        ERROR_LOG_FMT(NETPLAY, "enet_host_service: unknown event type: {}", int(netEvent.type));
         break;
       }
     }
+    else if (net == 0)
+    {
+      INFO_LOG_FMT(NETPLAY, "enet_host_service: no event occurred");
+    }
+    else
+    {
+      ERROR_LOG_FMT(NETPLAY, "enet_host_service error: {}", net);
+    }
   }
 
+  INFO_LOG_FMT(NETPLAY, "NetPlayClient shutting down.");
+
   Disconnect();
   return;
 }

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
@@ -268,8 +270,10 @@ void NetPlayServer::ThreadFunc()
     net = enet_host_service(m_server, &netEvent, 1000);
     while (!m_async_queue.Empty())
     {
+      INFO_LOG_FMT(NETPLAY, "Processing async queue event.");
       {
         std::lock_guard lkp(m_crit.players);
+        INFO_LOG_FMT(NETPLAY, "Locked player mutex.");
         auto& e = m_async_queue.Front();
         if (e.target_mode == TargetMode::Only)
         {
@@ -281,6 +285,7 @@ void NetPlayServer::ThreadFunc()
           SendToClients(e.packet, e.target_pid, e.channel_id);
         }
       }
+      INFO_LOG_FMT(NETPLAY, "Processing async queue event done.");
       m_async_queue.Pop();
     }
     if (net > 0)
@@ -297,6 +302,8 @@ void NetPlayServer::ThreadFunc()
       break;
       case ENET_EVENT_TYPE_RECEIVE:
       {
+        INFO_LOG_FMT(NETPLAY, "enet_host_service: receive event");
+
         sf::Packet rpac;
         rpac.append(netEvent.packet->data, netEvent.packet->dataLength);
 
@@ -305,12 +312,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,37 +338,65 @@ 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);
 
             ClearPeerPlayerId(netEvent.peer);
           }
+          else
+          {
+            INFO_LOG_FMT(NETPLAY, "successfully handled packet from client {}", client.pid);
+          }
         }
         enet_packet_destroy(netEvent.packet);
       }
       break;
       case ENET_EVENT_TYPE_DISCONNECT:
       {
+        INFO_LOG_FMT(NETPLAY, "enet_host_service: disconnect event");
+
         std::lock_guard lkg(m_crit.game);
         if (!netEvent.peer->data)
+        {
+          ERROR_LOG_FMT(NETPLAY, "enet_host_service: no peer data");
           break;
-        auto it = m_players.find(*PeerPlayerId(netEvent.peer));
+        }
+        const auto player_id = *PeerPlayerId(netEvent.peer);
+        auto it = m_players.find(player_id);
         if (it != m_players.end())
         {
           Client& client = it->second;
+          INFO_LOG_FMT(NETPLAY, "Disconnecting client {}.", client.pid);
           OnDisconnect(client);
 
           ClearPeerPlayerId(netEvent.peer);
         }
+        else
+        {
+          ERROR_LOG_FMT(NETPLAY, "Invalid player {} to disconnect.", player_id);
+        }
       }
       break;
       default:
+        ERROR_LOG_FMT(NETPLAY, "enet_host_service: unknown event type: {}", int(netEvent.type));
         break;
       }
     }
+    else if (net == 0)
+    {
+      INFO_LOG_FMT(NETPLAY, "enet_host_service: no event occurred");
+    }
+    else
+    {
+      ERROR_LOG_FMT(NETPLAY, "enet_host_service error: {}", net);
+    }
   }
 
+  INFO_LOG_FMT(NETPLAY, "NetPlayServer shutting down.");
+
   // close listening socket and client sockets
   for (auto& player_entry : m_players)
   {
@@ -699,7 +739,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 +1125,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 +1137,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 +1182,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 +1194,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 +1276,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 +1321,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 +1473,8 @@ struct SaveSyncInfo
 // called from ---GUI--- thread
 bool NetPlayServer::RequestStartGame()
 {
+  INFO_LOG_FMT(NETPLAY, "Start Game requested.");
+
   if (!SetupNetSettings())
     return false;
 
@@ -1452,12 +1532,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 +1660,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 +1706,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 +1752,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 +2008,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 +2051,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 +2079,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 +2101,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 +2129,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 +2148,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 +2326,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 +2368,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 +2393,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 +2418,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 +2433,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 +2450,8 @@ void NetPlayServer::ChunkedDataThreadFunc()
       m_chunked_data_queue.Pop();
     }
   }
+
+  INFO_LOG_FMT(NETPLAY, "Stopping Chunked Data Thread.");
 }
 
 // called from ---Chunked Data--- thread