diff --git a/Minecraft.Client/MinecraftServer.cpp b/Minecraft.Client/MinecraftServer.cpp index f1d40c07..005c49c4 100644 --- a/Minecraft.Client/MinecraftServer.cpp +++ b/Minecraft.Client/MinecraftServer.cpp @@ -1544,6 +1544,12 @@ void MinecraftServer::stopServer(bool didInit) } } } + // connection->stop() enqueued disconnects; the run loop is gone, so + // drain now or DisconnectPacket + sendAndQuit() never fire. + if (players != nullptr) + { + players->drainPendingDisconnects(); + } // reset the primary player signout flag m_bPrimaryPlayerSignedOut=false; s_bServerHalted = false; diff --git a/Minecraft.Client/PlayerList.cpp b/Minecraft.Client/PlayerList.cpp index edbfe7ac..531afb89 100644 --- a/Minecraft.Client/PlayerList.cpp +++ b/Minecraft.Client/PlayerList.cpp @@ -121,6 +121,45 @@ void PlayerList::queueDisconnect(shared_ptr player, int reason, co LeaveCriticalSection(&m_disconnectCS); } +void PlayerList::drainPendingDisconnects() +{ + std::deque dcCopy; + EnterCriticalSection(&m_disconnectCS); + dcCopy.swap(m_pendingDisconnects); + LeaveCriticalSection(&m_disconnectCS); + + while (!dcCopy.empty()) + { + PendingDisconnect pd = dcCopy.front(); + dcCopy.pop_front(); + + server->getPlayers()->removePlayerFromReceiving(pd.player); + if (pd.player->connection != nullptr) + { + pd.player->connection->send(std::make_shared(static_cast(pd.reason))); + pd.player->connection->connection->sendAndQuit(); + } + + if (!pd.kickMessage.empty()) + { + broadcastAll(std::make_shared(pd.kickMessage)); + } + else if (!pd.fourKitHandledQuit) + { + if (pd.wasKicked) + { + broadcastAll(std::make_shared(pd.player->name, ChatPacket::e_ChatPlayerKickedFromGame)); + } + else + { + broadcastAll(std::make_shared(pd.player->name, ChatPacket::e_ChatPlayerLeftGame)); + } + } + + remove(pd.player); + } +} + bool PlayerList::placeNewPlayer(Connection *connection, shared_ptr player, shared_ptr packet) { CompoundTag *playerTag = load(player); @@ -1300,43 +1339,7 @@ void PlayerList::tick() // Drain the pending disconnect queue. disconnect() enqueues here so it // can release done_cs before the heavy cleanup runs on the tick thread. - { - std::deque dcCopy; - EnterCriticalSection(&m_disconnectCS); - dcCopy.swap(m_pendingDisconnects); - LeaveCriticalSection(&m_disconnectCS); - - while (!dcCopy.empty()) - { - PendingDisconnect pd = dcCopy.front(); - dcCopy.pop_front(); - - server->getPlayers()->removePlayerFromReceiving(pd.player); - if (pd.player->connection != nullptr) - { - pd.player->connection->send(std::make_shared(static_cast(pd.reason))); - pd.player->connection->connection->sendAndQuit(); - } - - if (!pd.kickMessage.empty()) - { - broadcastAll(std::make_shared(pd.kickMessage)); - } - else if (!pd.fourKitHandledQuit) - { - if (pd.wasKicked) - { - broadcastAll(std::make_shared(pd.player->name, ChatPacket::e_ChatPlayerKickedFromGame)); - } - else - { - broadcastAll(std::make_shared(pd.player->name, ChatPacket::e_ChatPlayerLeftGame)); - } - } - - remove(pd.player); - } - } + drainPendingDisconnects(); // Drain the close queue: snapshot the deque, then release the CS before // calling disconnect() which may itself try to acquire other locks. diff --git a/Minecraft.Client/PlayerList.h b/Minecraft.Client/PlayerList.h index 1265ad24..001068d1 100644 --- a/Minecraft.Client/PlayerList.h +++ b/Minecraft.Client/PlayerList.h @@ -98,6 +98,7 @@ public: void move(shared_ptr player); void remove(shared_ptr player); void queueDisconnect(shared_ptr player, int reason, const wstring& kickMessage, bool wasKicked, bool fourKitHandledQuit); + void drainPendingDisconnects(); shared_ptr getPlayerForLogin(PendingConnection *pendingConnection, const wstring& userName, PlayerUID xuid, PlayerUID OnlineXuid); shared_ptr respawn(shared_ptr serverPlayer, int targetDimension, bool keepAllPlayerData); void toggleDimension(shared_ptr player, int targetDimension); diff --git a/Minecraft.Server/Windows64/ServerMain.cpp b/Minecraft.Server/Windows64/ServerMain.cpp index 33eecfde..f698f5dc 100644 --- a/Minecraft.Server/Windows64/ServerMain.cpp +++ b/Minecraft.Server/Windows64/ServerMain.cpp @@ -784,6 +784,16 @@ int main(int argc, char **argv) MinecraftServer *server = MinecraftServer::getInstance(); if (server != NULL) { + // A queued autosave action would spawn a bg save that races with the + // exit save's Flush() on the singleton CSaveGame::m_pSaveData buffer. + if (app.GetXuiServerAction(kServerActionPad) != eXuiServerAction_Idle) + { + LogWorldIO("Waiting for pending XUI server action before exit save..."); + if (!WaitForWorldActionIdle(kServerActionPad, 30000, &TickCoreSystems, &HandleXuiActions)) + { + LogWorldIO("XUI server action drain timed out; continuing with exit save"); + } + } // Drain any in-flight autosave before requesting the exit save so the // async autosave can't overwrite the exit save with an older snapshot, // and so m_saveOnExit gets set (prior logic skipped it when a save was @@ -822,10 +832,30 @@ int main(int argc, char **argv) waitThread.WaitForCompletion(INFINITE); } - while (ConsoleSaveFileOriginal::hasPendingBackgroundSave()) + if (ConsoleSaveFileOriginal::hasPendingBackgroundSave()) { - TickCoreSystems(); - Sleep(10); + LogWorldIO("waiting for exit save to land on disk..."); + const DWORD kExitDrainTimeoutMs = 60000; + const DWORD drainStart = GetTickCount(); + bool timedOut = false; + while (ConsoleSaveFileOriginal::hasPendingBackgroundSave()) + { + if ((LONG)(GetTickCount() - drainStart) > (LONG)kExitDrainTimeoutMs) + { + timedOut = true; + break; + } + TickCoreSystems(); + Sleep(10); + } + if (timedOut) + { + LogWarn("world-io", "exit save drain TIMED OUT; save may be incomplete"); + } + else + { + LogWorldIO("exit save drain complete"); + } } LogInfof("shutdown", "Cleaning up and exiting."); diff --git a/Minecraft.World/ConsoleSaveFileOriginal.cpp b/Minecraft.World/ConsoleSaveFileOriginal.cpp index 5c562430..ef301e97 100644 --- a/Minecraft.World/ConsoleSaveFileOriginal.cpp +++ b/Minecraft.World/ConsoleSaveFileOriginal.cpp @@ -16,6 +16,7 @@ #include #include #include +#include "ServerLogger.h" static std::atomic s_bgSaveActive{false}; static std::mutex s_bgSaveMutex; @@ -28,8 +29,20 @@ struct BackgroundSaveResult BYTE textMeta[88] = {}; int textMetaBytes = 0; bool pending = false; + bool isAutosave = false; + int64_t startTickMs = 0; + unsigned int rawBytes = 0; + unsigned int compressedBytes = 0; }; static BackgroundSaveResult s_bgResult; + +// Snapshotted under s_bgSaveMutex; SaveSaveDataCallback reads without +// re-locking (std::mutex is non-recursive, callback fires synchronously +// inside SaveSaveData while flushPendingBackgroundSave holds the lock). +static bool s_lastSaveIsAutosave = false; +static int64_t s_lastSaveStartTickMs = 0; +static unsigned int s_lastSaveRawBytes = 0; +static unsigned int s_lastSaveCompressedBytes = 0; #endif @@ -729,11 +742,18 @@ void ConsoleSaveFileOriginal::Flush(bool autosave, bool updateThumbnail ) StorageManager.GetSaveUniqueNumber(&uid); TelemetryManager->RecordLevelSaveOrCheckpoint(ProfileManager.GetPrimaryPad(), uid, fileSize); + const int64_t startMs = static_cast(GetTickCount()); + const bool modeAutosave = autosave; + ServerRuntime::LogInfof("world-io", + "save started: mode=%s raw=%u bytes", + modeAutosave ? "autosave" : "exit", fileSize); + ReleaseSaveAccess(); s_bgSaveActive.store(true, std::memory_order_release); - std::thread([snap, fileSize, thumb, thumbSz, meta, metaLen, this]() { + std::thread([snap, fileSize, thumb, thumbSz, meta, metaLen, modeAutosave, startMs, this]() { Compression::UseDefaultThreadStorage(); + const int64_t compStartMs = static_cast(GetTickCount()); unsigned int compLen = fileSize + 8; byte *buf = static_cast(StorageManager.AllocateSaveData(compLen)); if (!buf) @@ -751,6 +771,11 @@ void ConsoleSaveFileOriginal::Flush(bool autosave, bool updateThumbnail ) ZeroMemory(buf, 8); memcpy(buf + 4, &fileSize, sizeof(fileSize)); + const int64_t compMs = static_cast(GetTickCount()) - compStartMs; + ServerRuntime::LogInfof("world-io", + "save compressed: %u->%u bytes in %lldms", + fileSize, compLen, (long long)compMs); + // store the result so flushPendingBackgroundSave() can pick it up on the main thread next tick // StorageManager isnt thread safe so we cant call SetSaveImages or SaveSaveData from here. Bwoomp std::lock_guard lk(s_bgSaveMutex); @@ -759,11 +784,17 @@ void ConsoleSaveFileOriginal::Flush(bool autosave, bool updateThumbnail ) s_bgResult.thumbSize = thumbSz; memcpy(s_bgResult.textMeta, meta, sizeof(meta)); s_bgResult.textMetaBytes = metaLen; + s_bgResult.isAutosave = modeAutosave; + s_bgResult.startTickMs = startMs; + s_bgResult.rawBytes = fileSize; + s_bgResult.compressedBytes = compLen; s_bgResult.pending = true; } else { app.DebugPrintf("save buf alloc failed\n"); + ServerRuntime::LogError("world-io", + "save compression failed: out of memory; save dropped"); s_bgSaveActive.store(false, std::memory_order_release); } delete[] snap; @@ -771,6 +802,7 @@ void ConsoleSaveFileOriginal::Flush(bool autosave, bool updateThumbnail ) return; } app.DebugPrintf("snapshot alloc failed (%u bytes)\n", fileSize); + ServerRuntime::LogError("world-io", "save snapshot allocation failed; save dropped"); #endif // Assume that the compression will make it smaller so initially attempt to allocate the current file size @@ -984,6 +1016,22 @@ int ConsoleSaveFileOriginal::SaveSaveDataCallback(LPVOID lpParam,bool bRes) #endif #ifdef MINECRAFT_SERVER_BUILD + { + const int64_t totalMs = static_cast(GetTickCount()) - s_lastSaveStartTickMs; + const char *mode = s_lastSaveIsAutosave ? "autosave" : "exit"; + if (bRes) + { + ServerRuntime::LogInfof("world-io", + "save write completed: mode=%s raw=%u compressed=%u total=%lldms", + mode, s_lastSaveRawBytes, s_lastSaveCompressedBytes, (long long)totalMs); + } + else + { + ServerRuntime::LogErrorf("world-io", + "save write FAILED: mode=%s raw=%u compressed=%u total=%lldms", + mode, s_lastSaveRawBytes, s_lastSaveCompressedBytes, (long long)totalMs); + } + } s_bgSaveActive.store(false, std::memory_order_release); #endif @@ -1238,17 +1286,32 @@ void *ConsoleSaveFileOriginal::getWritePointer(FileEntry *file) #ifdef MINECRAFT_SERVER_BUILD void ConsoleSaveFileOriginal::flushPendingBackgroundSave() { - std::lock_guard lk(s_bgSaveMutex); - if (!s_bgResult.pending) - return; + PBYTE thumbData = nullptr; + DWORD thumbSize = 0; + BYTE textMeta[88] = {}; + int textMetaBytes = 0; + void *owner = nullptr; + { + std::lock_guard lk(s_bgSaveMutex); + if (!s_bgResult.pending) + return; - StorageManager.SetSaveImages( - s_bgResult.thumbData, s_bgResult.thumbSize, - nullptr, 0, s_bgResult.textMeta, s_bgResult.textMetaBytes); - StorageManager.SaveSaveData(&ConsoleSaveFileOriginal::SaveSaveDataCallback, s_bgResult.owner); + thumbData = s_bgResult.thumbData; + thumbSize = s_bgResult.thumbSize; + memcpy(textMeta, s_bgResult.textMeta, sizeof(textMeta)); + textMetaBytes = s_bgResult.textMetaBytes; + owner = s_bgResult.owner; - s_bgResult.pending = false; - // the actual write isnt done until SaveSaveDataCallback fires + s_lastSaveIsAutosave = s_bgResult.isAutosave; + s_lastSaveStartTickMs = s_bgResult.startTickMs; + s_lastSaveRawBytes = s_bgResult.rawBytes; + s_lastSaveCompressedBytes = s_bgResult.compressedBytes; + + s_bgResult.pending = false; + } + + StorageManager.SetSaveImages(thumbData, thumbSize, nullptr, 0, textMeta, textMetaBytes); + StorageManager.SaveSaveData(&ConsoleSaveFileOriginal::SaveSaveDataCallback, owner); } bool ConsoleSaveFileOriginal::hasPendingBackgroundSave()