Various debug logging tweaks

lib/gamelib/gtime.cpp

@@ -425,6 +425,8 @@ void sendPlayerGameTime()
 		NETuint16_t(&wantedLatency);
 		NETend();
 	}
+
+	debugVerboseLogSyncIfNeeded();
 }
 
 static inline bool shouldWaitForPlayerSlot(unsigned player)

lib/netplay/netplay.cpp

@@ -91,6 +91,7 @@
 char masterserver_name[255] = {'\0'};
 static unsigned int masterserver_port = 0, gameserver_port = 0;
 static bool bJoinPrefTryIPv6First = true;
+static uint32_t verboseDebugOutputAllSyncLogsUntilGameTime = 0;
 
 // This is for command line argument override
 // Disables port saving and reading from/to config
@@ -4901,6 +4902,18 @@ const char *NETgetMasterserverName()
 	return masterserver_name;
 }
 
+// Set whether verbose debug mode - outputting the current player's sync log for every single game tick - is enabled
+// WARNING: This may significantly impact performance *and* will fill up your drive with a lot of logs data!
+// It is only intended to be used for debugging issues such as: replays desyncing when gameplay does not, etc. (And don't let the game run too long!)
+void NET_setDebuggingModeVerboseOutputAllSyncLogs(uint32_t untilGameTime)
+{
+	verboseDebugOutputAllSyncLogsUntilGameTime = untilGameTime;
+	if (verboseDebugOutputAllSyncLogsUntilGameTime)
+	{
+		debug(LOG_INFO, "WARNING: Verbose sync log output is enabled!");
+	}
+}
+
 /*!
  * Set the masterserver port
  * \param port The port of the masterserver to connect to
@@ -5366,16 +5379,25 @@ GameCrcType nextDebugSync()
 	return (GameCrcType)ret;
 }
 
-static void dumpDebugSync(uint8_t *buf, size_t bufLen, uint32_t time, unsigned player, bool syncError = true)
+static void dumpDebugSyncImpl(uint8_t *buf, size_t bufLen, const char* fname)
 {
-	char fname[100];
-	PHYSFS_file *fp;
-
-	ssprintf(fname, "logs/desync%u_p%u.txt", time, player);
-	fp = openSaveFile(fname);
+	PHYSFS_file *fp = openSaveFile(fname);
+	if (!fp)
+	{
+		debug(LOG_ERROR, "Failed to open file for writing: %s", fname);
+		return;
+	}
 	ASSERT(bufLen <= static_cast<size_t>(std::numeric_limits<PHYSFS_uint32>::max()), "bufLen (%zu) exceeds PHYSFS_uint32::max", bufLen);
 	WZ_PHYSFS_writeBytes(fp, buf, static_cast<PHYSFS_uint32>(bufLen));
 	PHYSFS_close(fp);
+}
+
+static void dumpDebugSync(uint8_t *buf, size_t bufLen, uint32_t time, unsigned player, bool syncError = true)
+{
+	char fname[100];
+	ssprintf(fname, "logs/desync%u_p%u.txt", time, player);
+
+	dumpDebugSyncImpl(buf, bufLen, fname);
 
 	bool isSpectator = player < NetPlay.players.size() && NetPlay.players[player].isSpectator;
 	std::string typeDescription = (syncError) ? "sync error" : "sync log";
@@ -5454,6 +5476,22 @@ static void recvDebugSync(NETQUEUE queue)
 	}
 }
 
+void debugVerboseLogSyncIfNeeded()
+{
+	if (!verboseDebugOutputAllSyncLogsUntilGameTime || gameTime > verboseDebugOutputAllSyncLogsUntilGameTime)
+	{
+		return;
+	}
+
+	auto bufLen = dumpLocalDebugSyncLogByTime(gameTime);
+	if (bufLen > 0)
+	{
+		char fname[100];
+		ssprintf(fname, "logs/sync%u_p%u.txt", gameTime, selectedPlayer);
+		dumpDebugSyncImpl(debugSyncTmpBuf, bufLen, fname);
+	}
+}
+
 bool checkDebugSync(uint32_t checkGameTime, GameCrcType checkCrc)
 {
 	if (checkGameTime == syncDebugLog[syncDebugNext].getGameTime())  // Can't happen - and syncDebugGameTime[] == 0, until just before sending the CRC, anyway.

lib/netplay/netplay.h

@@ -524,6 +524,14 @@ void resetSyncDebug();                                              ///< Resets
 GameCrcType nextDebugSync();                                        ///< Returns a CRC corresponding to all syncDebug() calls since the last nextDebugSync() or resetSyncDebug() call.
 bool checkDebugSync(uint32_t checkGameTime, GameCrcType checkCrc);  ///< Dumps all syncDebug() calls from that gameTime, if the CRC doesn't match.
 
+
+// Set whether verbose debug mode - outputting the current player's sync log for every single game tick - is enabled until a specific gameTime value
+// WARNING: This may significantly impact performance *and* will fill up your drive with a lot of logs data!
+// It is only intended to be used for debugging issues such as: replays desyncing when gameplay does not, etc. (And don't let the game run too long / set untilGameTime too high!)
+void NET_setDebuggingModeVerboseOutputAllSyncLogs(uint32_t untilGameTime = 0);
+void debugVerboseLogSyncIfNeeded();
+
+
 /**
  * This structure provides read-only access to a player, and can be used to identify players uniquely.
  *

src/action.cpp

@@ -993,7 +993,21 @@ void actionUpdateDroid(DROID *psDroid)
 		{
 			break;
 		}
-		ASSERT_OR_RETURN(, psDroid->psActionTarget[0] != nullptr, "target is NULL while attacking");
+
+		if (psDroid->psActionTarget[0] == nullptr)
+		{
+			if (psDroid->numWeaps > 1)
+			{
+				// FUTURE TODO: Figure out what (if any) changes to this switch case might make sense for multi-weapon bodies
+				// To avoid log spam, make this a silent return for now
+				return;
+			}
+			else
+			{
+				// For single-weapon bodies, ASSERT
+				ASSERT_OR_RETURN(, psDroid->psActionTarget[0] != nullptr, "target is NULL while attacking");
+			}
+		}
 
 		if (psDroid->action == DACTION_ROTATETOATTACK)
 		{

src/clparse.cpp

@@ -357,7 +357,8 @@ typedef enum
 	CLI_GAMELOG_OUTPUTNAMING,
 	CLI_GAMELOG_FRAMEINTERVAL,
 	CLI_GAMETIMELIMITMINUTES,
-	CLI_CONVERT_SPECULAR_MAP
+	CLI_CONVERT_SPECULAR_MAP,
+	CLI_DEBUG_VERBOSE_SYNCLOG_OUTPUT
 } CLI_OPTIONS;
 
 // Separate table that avoids *any* translated strings, to avoid any risk of gettext / libintl function calls
@@ -443,6 +444,7 @@ static const struct poptOption *getOptionsTable()
 		{ "gamelog-frameinterval", POPT_ARG_STRING, CLI_GAMELOG_FRAMEINTERVAL, N_("Game history log frame interval"), N_("interval in seconds")},
 		{ "gametimelimit", POPT_ARG_STRING, CLI_GAMETIMELIMITMINUTES, N_("Multiplayer game time limit (in minutes)"), N_("number of minutes")},
 		{ "convert-specular-map", POPT_ARG_STRING, CLI_CONVERT_SPECULAR_MAP, N_("Convert a specular-map .png to a luma, single-channel, grayscale .png (and exit)"), "inputpath/filename.png:outputpath/filename.png" },
+		{ "debug-verbose-sync-logs-until", POPT_ARG_STRING, CLI_DEBUG_VERBOSE_SYNCLOG_OUTPUT, nullptr, nullptr },
 
 		// Terminating entry
 		{ nullptr, 0, 0,              nullptr,                                    nullptr },
@@ -1262,6 +1264,15 @@ bool ParseCommandLine(int argc, const char * const *argv)
 			break;
 		}
 
+		case CLI_DEBUG_VERBOSE_SYNCLOG_OUTPUT:
+			token = poptGetOptArg(poptCon);
+			if (token == nullptr)
+			{
+				qFatal("Bad debug verbose synclog output gametime limit");
+			}
+			NET_setDebuggingModeVerboseOutputAllSyncLogs(atoi(token));
+			break;
+
 		} // switch (option)
 	} // while
 

src/input/mapping.cpp

@@ -375,7 +375,7 @@ bool KeyMappings::save(const char* path) const
 		return false;
 	}
 
-	ini.setValue("version", 1);
+	ini.setValue("version", 2);
 
 	ini.beginArray("mappings");
 	for (const KeyMapping& mapping : keyMappings)

src/map.cpp

@@ -139,6 +139,41 @@ static std::unique_ptr<bool[]> mapDecals;           // array that tells us what
 /* Look up table that returns the terrain type of a given tile texture */
 UBYTE terrainTypes[MAX_TILE_TEXTURES];
 
+#if 0
+void syncLogDumpAuxMaps()
+{
+	for (int auxIdx = 0; auxIdx < MAX_PLAYERS + AUX_MAX; auxIdx++)
+	{
+		syncDebug("psAuxMap[%d]:", auxIdx);
+		for (int y = 0; y < mapHeight; ++y)
+		{
+			std::string rowDetails;
+			for (int x = 0; x < mapWidth; ++x)
+			{
+				auto val = auxTile(x, y, auxIdx);
+				rowDetails += std::to_string(val) + ",";
+			}
+			syncDebug("psAuxMap[%d] row[%d]: %s", auxIdx, y, rowDetails.c_str());
+		}
+	}
+
+	for (int idx = 0; idx < AUX_MAX; idx++)
+	{
+		syncDebug("psBlockMap[%d]:", idx);
+		for (int y = 0; y < mapHeight; ++y)
+		{
+			std::string rowDetails;
+			for (int x = 0; x < mapWidth; ++x)
+			{
+				auto val = blockTile(x, y, idx);
+				rowDetails += std::to_string(val) + ",";
+			}
+			syncDebug("psBlockMap[%d] row[%d]: %s", idx, y, rowDetails.c_str());
+		}
+	}
+}
+#endif
+
 const GROUND_TYPE& getGroundType(size_t idx)
 {
 	return groundTypes[idx];

src/mission.cpp

@@ -3097,7 +3097,10 @@ void clearMissionWidgets()
  */
 static DROID *find_transporter()
 {
-	ASSERT_OR_RETURN(nullptr, selectedPlayer < MAX_PLAYERS, "selectedPlayer %" PRIu32 " exceeds MAX_PLAYERS", selectedPlayer);
+	if (selectedPlayer >= MAX_PLAYERS)
+	{
+		return nullptr;
+	}
 
 	for (auto droid_list : {apsDroidLists[selectedPlayer], mission.apsDroidLists[selectedPlayer]})
 	{

src/multiplay.cpp

@@ -1988,7 +1988,7 @@ bool recvMapFileRequested(NETQUEUE queue)
 		filename = getModFilename(hash);
 		if (filename.empty())
 		{
-			debug(LOG_INFO, "Unknown file requested by %u.", player);
+			debug(LOG_INFO, "Unknown file requested by %u. (Hash: %s, loadedMods: %zu)", player, hash.toString().c_str(), getLoadedMods().size());
 			return false;
 		}