154 changes: 138 additions & 16 deletions Source/Core/Core/NetPlayServer.cpp
View file
Expand Up @@ -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
Expand Down Expand Up @@ -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)
{
Expand All @@ -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)
Expand All @@ -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);

Expand All @@ -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
Expand All @@ -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)
{
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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:
Expand All @@ -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;
Expand Down Expand Up @@ -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)
{
Expand All @@ -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;
Expand Down Expand Up @@ -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;

Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -1395,6 +1473,8 @@ struct SaveSyncInfo
// called from ---GUI--- thread
bool NetPlayServer::RequestStartGame()
{
INFO_LOG_FMT(NETPLAY, "Start Game requested.");

if (!SetupNetSettings())
return false;

Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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 ||
Config::Get(Config::GetInfoForEXIDevice(slot)) ==
ExpansionInterface::EXIDeviceType::MemoryCardFolder)
if (m_settings.exi_device[slot] == ExpansionInterface::EXIDeviceType::MemoryCard)
{
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;
}
}
Expand All @@ -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;

Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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;

Expand Down Expand Up @@ -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.
{
Expand All @@ -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;
}
Expand All @@ -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.
{
Expand All @@ -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;
}
Expand All @@ -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
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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()};
Expand All @@ -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;
Expand All @@ -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;

Expand All @@ -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;
Expand All @@ -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
Expand Down