Connection timeout and auto kick improvements

lib/netplay/netplay.cpp

@@ -1930,6 +1930,7 @@ static bool swapPlayerIndexes(uint32_t playerIndexA, uint32_t playerIndexB)
 	// Swap certain ingame player-associated entries
 	std::swap(ingame.PingTimes[playerIndexA], ingame.PingTimes[playerIndexB]);
 	std::swap(ingame.LagCounter[playerIndexA], ingame.LagCounter[playerIndexB]);
+	std::swap(ingame.DesyncCounter[playerIndexA], ingame.DesyncCounter[playerIndexB]);
 	std::swap(ingame.VerifiedIdentity[playerIndexA], ingame.VerifiedIdentity[playerIndexB]);
 	std::swap(ingame.JoiningInProgress[playerIndexA], ingame.JoiningInProgress[playerIndexB]);
 	std::swap(ingame.PendingDisconnect[playerIndexA], ingame.PendingDisconnect[playerIndexB]);

src/configuration.cpp

@@ -582,6 +582,7 @@ bool loadConfig()
 		pie_EnableFog(false);
 	}
 	war_setAutoLagKickSeconds(iniGetInteger("hostAutoLagKickSeconds", war_getAutoLagKickSeconds()).value());
+	war_setAutoDesyncKickSeconds(iniGetInteger("hostAutoDesyncKickSeconds", war_getAutoDesyncKickSeconds()).value());
 	war_setDisableReplayRecording(iniGetBool("disableReplayRecord", war_getDisableReplayRecording()).value());
 	war_setMaxReplaysSaved(iniGetInteger("maxReplaysSaved", war_getMaxReplaysSaved()).value());
 	war_setOldLogsLimit(iniGetInteger("oldLogsLimit", war_getOldLogsLimit()).value());
@@ -773,6 +774,7 @@ bool saveConfig()
 	iniSetBool("autosaveEnabled", autosaveEnabled);
 	iniSetBool("fog", pie_GetFogEnabled());
 	iniSetInteger("hostAutoLagKickSeconds", war_getAutoLagKickSeconds());
+	iniSetInteger("hostAutoDesyncKickSeconds", war_getAutoDesyncKickSeconds());
 	iniSetBool("disableReplayRecord", war_getDisableReplayRecording());
 	iniSetInteger("maxReplaysSaved", war_getMaxReplaysSaved());
 	iniSetInteger("oldLogsLimit", war_getOldLogsLimit());

src/multiint.cpp

@@ -6198,6 +6198,7 @@ bool WzMultiplayerOptionsTitleUI::startHost()
 		ingame.PingTimes[i] = 0;
 		ingame.VerifiedIdentity[i] = false;
 		ingame.LagCounter[i] = 0;
+		ingame.DesyncCounter[i] = 0;
 		ingame.lastSentPlayerDataCheck2[i].reset();
 		ingame.muteChat[i] = false;
 	}

src/multijoin.cpp

@@ -99,6 +99,7 @@ void clearPlayer(UDWORD player, bool quietly)
 	debug(LOG_NET, "R.I.P. %s (%u). quietly is %s", getPlayerName(player), player, quietly ? "true" : "false");
 
 	ingame.LagCounter[player] = 0;
+	ingame.DesyncCounter[player] = 0;
 	ingame.JoiningInProgress[player] = false;	// if they never joined, reset the flag
 	ingame.DataIntegrity[player] = false;
 	ingame.hostChatPermissions[player] = false;
@@ -332,6 +333,7 @@ void handlePlayerLeftInGame(UDWORD player)
 	debug(LOG_NET, "R.I.P. %s (%u).", getPlayerName(player), player);
 
 	ingame.LagCounter[player] = 0;
+	ingame.DesyncCounter[player] = 0;
 	ingame.JoiningInProgress[player] = false;	// if they never joined, reset the flag
 	ingame.PendingDisconnect[player] = false;
 	ingame.DataIntegrity[player] = false;
@@ -515,7 +517,10 @@ bool MultiPlayerLeave(UDWORD playerIndex)
 
 	if (widgGetFromID(psWScreen, IDRET_FORM))
 	{
-		audio_QueueTrack(ID_CLAN_EXIT);
+		if (playerIndex < MAX_PLAYERS) // only play audio when *player* slots drop (ignore spectator slots)
+		{
+			audio_QueueTrack(ID_CLAN_EXIT);
+		}
 	}
 
 	// fire script callback to reassign skirmish players.
@@ -671,6 +676,7 @@ void setupNewPlayer(UDWORD player)
 
 	ingame.PingTimes[player] = 0;					// Reset ping time
 	ingame.LagCounter[player] = 0;
+	ingame.DesyncCounter[player] = 0;
 	ingame.VerifiedIdentity[player] = false;
 	ingame.JoiningInProgress[player] = true;			// Note that player is now joining
 	ingame.PendingDisconnect[player] = false;

src/multiopt.cpp

@@ -724,6 +724,7 @@ bool multiGameShutdown()
 	ingame.startTime = std::chrono::steady_clock::time_point();
 	ingame.endTime = nullopt;
 	ingame.lastLagCheck = std::chrono::steady_clock::time_point();
+	ingame.lastDesyncCheck = std::chrono::steady_clock::time_point();
 	ingame.lastPlayerDataCheck2 = std::chrono::steady_clock::time_point();
 	NetPlay.isHost					= false;
 	bMultiPlayer					= false;	// Back to single player mode

src/multiplay.cpp

@@ -116,13 +116,13 @@ static bool sendDataCheck2();
 void startMultiplayerGame();
 
 // ////////////////////////////////////////////////////////////////////////////
-// Auto Lag Kick Handling
+// Auto Bad Connection Kick Handling
 
 #define LAG_INITIAL_LOAD_GRACEPERIOD 60
 #define LAG_CHECK_INTERVAL 1000
 const std::chrono::milliseconds LagCheckInterval(LAG_CHECK_INTERVAL);
 
-void autoLagKickRoutine()
+void autoLagKickRoutine(std::chrono::steady_clock::time_point now)
 {
 	if (!bMultiPlayer || !NetPlay.bComms || !NetPlay.isHost)
 	{
@@ -135,7 +135,6 @@ void autoLagKickRoutine()
 		return;
 	}
 
-	const std::chrono::steady_clock::time_point now = std::chrono::steady_clock::now();
 	if (std::chrono::duration_cast<std::chrono::milliseconds>(now - ingame.lastLagCheck) < LagCheckInterval)
 	{
 		return;
@@ -225,12 +224,103 @@ void autoLagKickRoutine()
 			ingame.LagCounter[i] = 0;
 		}
 		else if (ingame.LagCounter[i] >= (LagAutoKickSeconds - 3)) {
-			std::string msg = astringf("Auto-kicking player %" PRIu32 " (\"%s\") in %u seconds.", i, getPlayerName(i), (LagAutoKickSeconds - ingame.LagCounter[i]));
+			std::string msg = astringf("Auto-kicking player %" PRIu32 " (\"%s\") in %u seconds. (lag)", i, getPlayerName(i), (LagAutoKickSeconds - ingame.LagCounter[i]));
 			debug(LOG_INFO, "%s", msg.c_str());
 			sendInGameSystemMessage(msg.c_str());
 		}
 		else if (ingame.LagCounter[i] % 15 == 0) { // every 15 seconds
-			std::string msg = astringf("Auto-kicking player %" PRIu32 " (\"%s\") in %u seconds.", i, getPlayerName(i), (LagAutoKickSeconds - ingame.LagCounter[i]));
+			std::string msg = astringf("Auto-kicking player %" PRIu32 " (\"%s\") in %u seconds. (lag)", i, getPlayerName(i), (LagAutoKickSeconds - ingame.LagCounter[i]));
+			debug(LOG_INFO, "%s", msg.c_str());
+			sendInGameSystemMessage(msg.c_str());
+		}
+	}
+}
+
+void autoLagKickRoutine()
+{
+	if (!bMultiPlayer || !NetPlay.bComms || !NetPlay.isHost)
+	{
+		return;
+	}
+
+	const std::chrono::steady_clock::time_point now = std::chrono::steady_clock::now();
+	autoLagKickRoutine(now);
+}
+
+#define DESYNC_CHECK_INTERVAL 1000
+const std::chrono::milliseconds DesyncCheckInterval(DESYNC_CHECK_INTERVAL);
+
+void autoDesyncKickRoutine(std::chrono::steady_clock::time_point now)
+{
+	if (!bMultiPlayer || !NetPlay.bComms || !NetPlay.isHost)
+	{
+		return;
+	}
+
+	int DesyncAutoKickSeconds = war_getAutoDesyncKickSeconds();
+	if (DesyncAutoKickSeconds <= 0)
+	{
+		return;
+	}
+
+	if (std::chrono::duration_cast<std::chrono::milliseconds>(now - ingame.lastDesyncCheck) < DesyncCheckInterval)
+	{
+		return;
+	}
+
+	if (ingame.endTime.has_value())
+	{
+		// game ended - skip desync check / kick
+		return;
+	}
+
+	ingame.lastDesyncCheck = now;
+	uint32_t playerCheckLimit = MAX_PLAYERS;
+	for (uint32_t i = 0; i < playerCheckLimit; ++i)
+	{
+		if (!isHumanPlayer(i))
+		{
+			continue;
+		}
+		if (i == NetPlay.hostPlayer)
+		{
+			continue;
+		}
+		if (i > MAX_PLAYERS && !gtimeShouldWaitForPlayer(i))
+		{
+			continue;
+		}
+
+		bool isDesynced = NETcheckPlayerConnectionStatus(CONNECTIONSTATUS_DESYNC, i);
+
+		if (!isDesynced)
+		{
+			ingame.DesyncCounter[i] = 0;
+			continue;
+		}
+
+		if (ingame.PendingDisconnect[i])
+		{
+			// player already technically left, but we're still in the "pre-game" phase so the GAME_PLAYER_LEFT hasn't been processed yet
+			continue;
+		}
+
+		ingame.DesyncCounter[i]++;
+		if (ingame.DesyncCounter[i] >= DesyncAutoKickSeconds) {
+			std::string msg = astringf("Auto-kicking player %" PRIu32 " (\"%s\") because of desync. (Timeout: %u seconds)", i, getPlayerName(i), DesyncAutoKickSeconds);
+			debug(LOG_INFO, "%s", msg.c_str());
+			sendInGameSystemMessage(msg.c_str());
+			wz_command_interface_output("WZEVENT: desync-kick: %u %s\n", i, NetPlay.players[i].IPtextAddress);
+			kickPlayer(i, "Your game simulation deviated too far from the host - desync.", ERROR_CONNECTION, false);
+			ingame.DesyncCounter[i] = 0;
+		}
+		else if (ingame.DesyncCounter[i] >= (DesyncAutoKickSeconds - 3)) {
+			std::string msg = astringf("Auto-kicking player %" PRIu32 " (\"%s\") in %u seconds. (desync)", i, getPlayerName(i), (DesyncAutoKickSeconds - ingame.DesyncCounter[i]));
+			debug(LOG_INFO, "%s", msg.c_str());
+			sendInGameSystemMessage(msg.c_str());
+		}
+		else if (ingame.DesyncCounter[i] % 2 == 0) { // every 2 seconds
+			std::string msg = astringf("Auto-kicking player %" PRIu32 " (\"%s\") in %u seconds. (desync)", i, getPlayerName(i), (DesyncAutoKickSeconds - ingame.DesyncCounter[i]));
 			debug(LOG_INFO, "%s", msg.c_str());
 			sendInGameSystemMessage(msg.c_str());
 		}
@@ -414,7 +504,9 @@ bool multiPlayerLoop()
 
 	if (NetPlay.isHost)
 	{
-		autoLagKickRoutine();
+		const std::chrono::steady_clock::time_point now = std::chrono::steady_clock::now();
+		autoLagKickRoutine(now);
+		autoDesyncKickRoutine(now);
 		processPendingKickVotes();
 	}
 

src/multiplay.h

@@ -107,6 +107,7 @@ struct MULTIPLAYERINGAME
 {
 	UDWORD				PingTimes[MAX_CONNECTED_PLAYERS];				// store for pings.
 	int 				LagCounter[MAX_CONNECTED_PLAYERS];
+	int 				DesyncCounter[MAX_CONNECTED_PLAYERS];
 	bool				VerifiedIdentity[MAX_CONNECTED_PLAYERS];		// if the multistats identity has been verified.
 	bool				localOptionsReceived;							// used to show if we have game options yet..
 	bool				localJoiningInProgress;							// used before we know our player number.
@@ -120,6 +121,7 @@ struct MULTIPLAYERINGAME
 	std::chrono::steady_clock::time_point startTime;
 	optional<std::chrono::steady_clock::time_point> endTime;
 	std::chrono::steady_clock::time_point lastLagCheck;
+	std::chrono::steady_clock::time_point lastDesyncCheck;
 	optional<std::chrono::steady_clock::time_point> lastSentPlayerDataCheck2[MAX_CONNECTED_PLAYERS] = {};
 	std::chrono::steady_clock::time_point lastPlayerDataCheck2;
 	bool				muteChat[MAX_CONNECTED_PLAYERS] = {false};		// the local client-set mute status for this player

src/screens/joiningscreen.cpp

@@ -419,7 +419,7 @@ int32_t WzJoiningStatusForm::calculateNeededHeight(bool withDetailsParagraph)
 	}
 	else
 	{
-		result += statusDetails->height();
+		result += statusDetails->idealHeight();
 	}
 	result += InternalPadding;
 	if (passwordPrompt && passwordPrompt->visible())
@@ -521,7 +521,7 @@ void WzJoiningStatusForm::recalcLayout()
 
 	int statusDetailsX0 = InternalPadding;
 	int statusDetailsWidth = usableWidth;
-	statusDetails->setGeometry(statusDetailsX0, lastLineY1 + DetailsLabelParagraphPadding, statusDetailsWidth, statusDetails->height());
+	statusDetails->setGeometry(statusDetailsX0, lastLineY1 + DetailsLabelParagraphPadding, statusDetailsWidth, statusDetails->idealHeight());
 
 	int paragraphHeight = usableHeight - DetailsLabelParagraphPadding;
 	scrollableParagraphContainer->setGeometry(InternalPadding, lastLineY1 + DetailsLabelParagraphPadding, usableWidth, paragraphHeight);
@@ -546,7 +546,7 @@ void WzJoiningStatusForm::displayStatus(const WzString &statusDescription)
 	}
 	scrollableParagraphContainer->hide();
 
-	statusDetails->setString(statusDescription);
+	statusDetails->setFormattedString(statusDescription, std::numeric_limits<uint32_t>::max(), font_regular);
 	statusDetails->show();
 }
 
@@ -780,6 +780,10 @@ class WzJoiningGameScreen_HandlerRoot : public W_CLICKFORM
 	};
 	JoiningState currentJoiningState = JoiningState::AwaitingConnection;
 
+	const char* to_string(JoiningState s);
+	const char* to_display_str(JoiningState s);
+	const char* to_localized_state_fail_desc(JoiningState s);
+
 	// state when handling initial connection join
 	uint32_t startTime = 0;
 	Socket* client_transient_socket = nullptr;
@@ -956,12 +960,73 @@ void WzJoiningGameScreen_HandlerRoot::updateJoiningStatus(const WzString& status
 	joiningProgressForm->displayProgressStatus(statusDescription);
 }
 
+const char* WzJoiningGameScreen_HandlerRoot::to_string(JoiningState s)
+{
+	switch (s) {
+		case JoiningState::NeedsPassword: return "NeedsPassword";
+		case JoiningState::AwaitingConnection: return "AwaitingConnection";
+		case JoiningState::AwaitingInitialNetcodeHandshakeAck: return "AwaitingInitialNetcodeHandshakeAck";
+		case JoiningState::ProcessingJoinMessages: return "ProcessingJoinMessages";
+		case JoiningState::Failure: return "Failure";
+		case JoiningState::SuccessPendingClose: return "SuccessPendingClose";
+		case JoiningState::Success: return "Success";
+	}
+	return ""; // silence compiler warning
+}
+
+const char* WzJoiningGameScreen_HandlerRoot::to_display_str(JoiningState s)
+{
+	switch (s) {
+		case JoiningState::NeedsPassword: return "NeedsPassword";
+		case JoiningState::AwaitingConnection: return "PendingConnect";
+		case JoiningState::AwaitingInitialNetcodeHandshakeAck: return "NetcodeHandshake";
+		case JoiningState::ProcessingJoinMessages: return "ProcessingJoin";
+		case JoiningState::Failure: return "Failure";
+		case JoiningState::SuccessPendingClose: return "SuccessPendingClose";
+		case JoiningState::Success: return "Success";
+	}
+	return ""; // silence compiler warning
+}
+
+const char* WzJoiningGameScreen_HandlerRoot::to_localized_state_fail_desc(JoiningState s)
+{
+	switch (s) {
+		case JoiningState::NeedsPassword:
+			return _("Waiting for correct join password");
+		case JoiningState::AwaitingConnection:
+			return _("Attempting to connect");
+		case JoiningState::AwaitingInitialNetcodeHandshakeAck:
+			return _("Establishing connection handshake");
+		case JoiningState::ProcessingJoinMessages:
+			return _("Coordinating join with host");
+		case JoiningState::Failure:
+			return _("Join attempt failed");
+		case JoiningState::SuccessPendingClose:
+		case JoiningState::Success:
+			return "";
+	}
+	return ""; // silence compiler warning
+}
+
 void WzJoiningGameScreen_HandlerRoot::handleJoinTimeoutError()
 {
+	debug(LOG_INFO, "Failed to join with timeout, state: %s", to_string(currentJoiningState));
+
+	WzString timeoutErrorDetails = _("Host did not respond before timeout");
+	timeoutErrorDetails += "\n";
+	WzString localizedJoinStateDesc = to_localized_state_fail_desc(currentJoiningState);
+	if (!localizedJoinStateDesc.isEmpty())
+	{
+		timeoutErrorDetails += WzString::fromUtf8(astringf(_("Failed at: [%s] - %s"), to_display_str(currentJoiningState), localizedJoinStateDesc.toUtf8().c_str()));
+	}
+	else
+	{
+		timeoutErrorDetails += WzString::fromUtf8(astringf(_("Failed at: [%s]"), to_display_str(currentJoiningState)));
+	}
+
 	currentJoiningState = JoiningState::Failure;
 
-	debug(LOG_INFO, "Failed to join with timeout");
-	joiningProgressForm->displayUnableToJoinError(_("Host did not respond before timeout"));
+	joiningProgressForm->displayUnableToJoinError(timeoutErrorDetails);
 	joiningProgressForm->callCalcLayout();
 
 	if (onFailureFunc)

src/warzoneconfig.cpp

@@ -74,6 +74,7 @@ struct WARZONE_GLOBALS
 	JS_BACKEND jsBackend = (JS_BACKEND)0;
 	bool autoAdjustDisplayScale = true;
 	int autoLagKickSeconds = 60;
+	int autoDesyncKickSeconds = 10;
 	bool disableReplayRecording = false;
 	int maxReplaysSaved = MAX_REPLAY_FILES;
 	int oldLogsLimit = MAX_OLD_LOGS;
@@ -486,6 +487,21 @@ void war_setAutoLagKickSeconds(int seconds)
 	warGlobs.autoLagKickSeconds = seconds;
 }
 
+int war_getAutoDesyncKickSeconds()
+{
+	return warGlobs.autoDesyncKickSeconds;
+}
+
+void war_setAutoDesyncKickSeconds(int seconds)
+{
+	seconds = std::max(seconds, 0);
+	if (seconds > 0)
+	{
+		seconds = std::max(seconds, 10);
+	}
+	warGlobs.autoDesyncKickSeconds = seconds;
+}
+
 bool war_getDisableReplayRecording()
 {
 	return warGlobs.disableReplayRecording;

src/warzoneconfig.h

@@ -132,6 +132,8 @@ bool war_getAutoAdjustDisplayScale();
 void war_setAutoAdjustDisplayScale(bool autoAdjustDisplayScale);
 int war_getAutoLagKickSeconds();
 void war_setAutoLagKickSeconds(int seconds);
+int war_getAutoDesyncKickSeconds();
+void war_setAutoDesyncKickSeconds(int seconds);
 bool war_getDisableReplayRecording();
 void war_setDisableReplayRecording(bool disable);
 int war_getMaxReplaysSaved();