From bfe0940bbd2720bbf8b0446d106ce096285ae0e7 Mon Sep 17 00:00:00 2001 From: "Admiral H. Curtiss" Date: Thu, 30 Mar 2023 00:02:25 +0200 Subject: [PATCH 1/2] Netplay: More logging before game start. --- Source/Core/Core/NetPlayClient.cpp | 29 ++++++- Source/Core/Core/NetPlayServer.cpp | 124 +++++++++++++++++++++++++---- 2 files changed, 134 insertions(+), 19 deletions(-) diff --git a/Source/Core/Core/NetPlayClient.cpp b/Source/Core/Core/NetPlayClient.cpp index 9aa49255c3..acd21bc90e 100644 --- a/Source/Core/Core/NetPlayClient.cpp +++ b/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 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(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) diff --git a/Source/Core/Core/NetPlayServer.cpp b/Source/Core/Core/NetPlayServer.cpp index 7f461f83d4..0c3b50746c 100644 --- a/Source/Core/Core/NetPlayServer.cpp +++ b/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(mid)); + INFO_LOG_FMT(NETPLAY, "Got client message: {:x} from client {}", static_cast(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 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; } } @@ -1611,6 +1678,8 @@ std::optional 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 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> 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(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 From 0ccf24b0c51150eaddc99af2c31a9bb0c42937e6 Mon Sep 17 00:00:00 2001 From: "Admiral H. Curtiss" Date: Thu, 30 Mar 2023 16:56:04 +0200 Subject: [PATCH 2/2] Netplay: More logging for server and client thread main loops. --- Source/Core/Core/NetPlayClient.cpp | 22 ++++++++++++++++++++++ Source/Core/Core/NetPlayServer.cpp | 30 +++++++++++++++++++++++++++++- 2 files changed, 51 insertions(+), 1 deletion(-) diff --git a/Source/Core/Core/NetPlayClient.cpp b/Source/Core/Core/NetPlayClient.cpp index acd21bc90e..404ae5eef4 100644 --- a/Source/Core/Core/NetPlayClient.cpp +++ b/Source/Core/Core/NetPlayClient.cpp @@ -1581,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)) { @@ -1606,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) @@ -1617,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()) @@ -1631,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; } diff --git a/Source/Core/Core/NetPlayServer.cpp b/Source/Core/Core/NetPlayServer.cpp index 0c3b50746c..5d93906e2b 100644 --- a/Source/Core/Core/NetPlayServer.cpp +++ b/Source/Core/Core/NetPlayServer.cpp @@ -270,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) { @@ -283,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) @@ -299,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); @@ -341,16 +346,26 @@ void NetPlayServer::ThreadFunc() 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; @@ -359,12 +374,25 @@ void NetPlayServer::ThreadFunc() 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.");