(svn r14772) -Codechange: make the "dump log of game to reproduce" desync debug stuff a runtime configurable debug option instead of a compile time option.

config.lib

@@ -1357,10 +1357,7 @@ make_cflags_and_ldflags() {
 		CFLAGS="$CFLAGS -DNDEBUG"
 	fi
 
-	if [ "$enable_desync_debug" = "1" ]; then
-		CFLAGS="$CFLAGS -DDEBUG_DUMP_COMMANDS"
-	fi
-	if [ "$enable_desync_debug" = "2" ]; then
+	if [ "$enable_desync_debug" != "0" ]; then
 		CFLAGS="$CFLAGS -DRANDOM_DEBUG"
 	fi
 

readme.txt

@@ -66,6 +66,58 @@ Please include the following information in your bug report:
           the bug. That way we can fix it quicker by looking at the
           changes made.
 
+2.2) Reporting Desyncs:
+---- ------------------
+As desyncs are hard to make reproducable OpenTTD has the ability to log all
+actions done by clients so we can replay the whole game in an effort to make
+desyncs better reproducable. You need to turn this ability on. When turned
+on an automatic savegame will be made once the map has been constructed in
+the 'save/autosave' directory, see OpenTTD directories to know where to find
+this directory. Furthermore the log file 'commands-out.log' will be created
+and all actions will be written to there.
+
+To enable the desync debugging you need to set the debug level for 'desync'
+to at least 1. You do this by starting OpenTTD with '-d desync=<level>' as
+parameter or by typing 'debug_level desync=<level>' in OpenTTD's internal
+console.
+The desync debug levels are:
+ 0: nothing.
+ 1: dumping of commands to 'commands-out.log'.
+ 2: same as 1 plus checking vehicle caches and dumping that too.
+ 3: same as 2 plus monthly saves in autosave.
+ 4 and higher: same as 3
+
+Restarting OpenTTD will overwrite 'commands-out.log'. OpenTTD will not remove
+the savegames (dmp_cmds_*.sav) made by the desync debugging system, so you
+have to occasionally remove them yourself!
+
+The naming format of the desync savegames is as follows:
+dmp_cmds_XXXXXXXX_YYYYYYYY.sav. The XXXXXXXX is the hexadecimal representation
+of the generation seed of the game and YYYYYYYY is the hexadecimal
+representation of the date of the game. This sorts the savegames by game and
+then by date making it easier to find the right savegames.
+
+When a desync has occurred with the desync debugging turned on you should file
+a bug report with the following files attached:
+ - commands-out.log as it contains all the commands that were done
+ - the last saved savegame (search for the last line beginning with
+   'save: dmp_cmds_' in commands-out.log). We use this savegame to check
+   whether we can quickly reproduce the desync. Otherwise we will need...
+ - the first saved savegame (search for the first line beginning with 'save'
+   where the first part, up to the last underscore '_', is the same). We need
+   this savegame to be able to reproduce the bug when the last savegame is not
+   old enough. If you loaded a scenario or savegame you need to attach that.
+ - optionally you can attach the savegames from around 50%, 75%, 85%, 90% and
+   95% of the game's progression. We can use these savegames to speed up the
+   reproduction of the desync, but we should be able to reproduce these
+   savegames based on the first savegame and commands-out.log.
+ - in case you use any NewGRFs you should attach the ones you used unless
+   we can easily find them ourselves via e.g. grfcrawler or when they are
+   in the OpenTTDCoop pack.
+
+Do NOT remove the dmp_cmds savegames of a desync you have reported until the
+desync has been fixed; if you, by accident, send us the wrong savegames we
+will not be able to reproduce the desync and thus will be unable to fix it.
 
 3.0) Supported Platforms:
 ---- --------------------

src/command.cpp

@@ -583,7 +583,7 @@ bool DoCommandP(TileIndex tile, uint32 p1, uint32 p2, uint32 cmd, CommandCallbac
 		return true;
 	}
 #endif /* ENABLE_NETWORK */
-	DebugDumpCommands("ddc:cmd:%d;%d;%d;%d;%d;%d;%d;%s\n", _date, _date_fract, (int)_current_company, tile, p1, p2, cmd, text);
+	DEBUG(desync, 1, "cmd: %08x; %08x; %1x; %06x; %08x; %08x; %04x; %s\n", _date, _date_fract, (int)_current_company, tile, p1, p2, cmd & ~CMD_NETWORK_COMMAND, text);
 
 	/* update last build coordinate of company. */
 	if (tile != 0 && IsValidCompanyID(_current_company)) {

src/date.cpp

@@ -15,9 +15,7 @@
 #include "vehicle_base.h"
 #include "debug.h"
 #include "rail_gui.h"
-#ifdef DEBUG_DUMP_COMMANDS
 #include "saveload.h"
-#endif
 
 Year      _cur_year;
 Month     _cur_month;
@@ -244,12 +242,12 @@ void IncreaseDate()
 
 	/* yes, call various monthly loops */
 	if (_game_mode != GM_MENU) {
-#ifdef DEBUG_DUMP_COMMANDS
-		char name[MAX_PATH];
-		snprintf(name, lengthof(name), "dmp_cmds_%d.sav", _date);
-		SaveOrLoad(name, SL_SAVE, AUTOSAVE_DIR);
-		DebugDumpCommands("ddc:save:%s\n", name);
-#endif /* DUMP_COMMANDS */
+		if (_debug_desync_level > 2) {
+			char name[MAX_PATH];
+			snprintf(name, lengthof(name), "dmp_cmds_%08x_%08x.sav", _settings_game.game_creation.generation_seed, _date);
+			SaveOrLoad(name, SL_SAVE, AUTOSAVE_DIR);
+		}
+
 		if (_settings_client.gui.autosave != 0 && (_cur_month % _autosave_months[_settings_client.gui.autosave]) == 0) {
 			_do_autosave = true;
 			RedrawAutosave();

src/debug.cpp

@@ -10,6 +10,7 @@
 #include "debug.h"
 #include "string_func.h"
 #include "network/core/core.h"
+#include "fileio_func.h"
 
 #if defined(ENABLE_NETWORK)
 SOCKET _debug_socket = INVALID_SOCKET;
@@ -31,6 +32,7 @@ int _debug_freetype_level;
 int _debug_sl_level;
 int _debug_station_level;
 int _debug_gamelog_level;
+int _debug_desync_level;
 
 
 struct DebugLevel {
@@ -56,6 +58,7 @@ struct DebugLevel {
 	DEBUG_LEVEL(sl),
 	DEBUG_LEVEL(station),
 	DEBUG_LEVEL(gamelog),
+	DEBUG_LEVEL(desync),
 	};
 #undef DEBUG_LEVEL
 
@@ -71,7 +74,7 @@ static void debug_print(const char *dbg, const char *buf)
 		send(_debug_socket, buf2, (int)strlen(buf2), 0);
 	} else
 #endif /* ENABLE_NETWORK */
-	{
+	if (strcmp(dbg, "desync") != 0) {
 #if defined(WINCE)
 		/* We need to do OTTD2FS twice, but as it uses a static buffer, we need to store one temporary */
 		TCHAR tbuf[512];
@@ -81,6 +84,12 @@ static void debug_print(const char *dbg, const char *buf)
 		fprintf(stderr, "dbg: [%s] %s\n", dbg, buf);
 #endif
 		IConsoleDebug(dbg, buf);
+	} else {
+		static FILE *f = FioFOpenFile("commands-out.log", "wb", AUTOSAVE_DIR);
+		if (f == NULL) return;
+
+		fprintf(f, "%s", buf);
+		fflush(f);
 	}
 }
 
@@ -168,20 +177,3 @@ const char *GetDebugString()
 
 	return dbgstr;
 }
-
-#ifdef DEBUG_DUMP_COMMANDS
-#include "fileio_func.h"
-
-void CDECL DebugDumpCommands(const char *s, ...)
-{
-	static FILE *f = FioFOpenFile("commands-out.log", "wb", AUTOSAVE_DIR);
-	if (f == NULL) return;
-
-	va_list va;
-	va_start(va, s);
-	vfprintf(f, s, va);
-	va_end(va);
-
-	fflush(f);
-}
-#endif /* DEBUG_DUMP_COMMANDS */

src/debug.h

@@ -48,6 +48,7 @@
 	extern int _debug_sl_level;
 	extern int _debug_station_level;
 	extern int _debug_gamelog_level;
+	extern int _debug_desync_level;
 
 	void CDECL debug(const char *dbg, ...);
 #endif /* NO_DEBUG_MESSAGES */
@@ -101,16 +102,4 @@ const char *GetDebugString();
 void ShowInfo(const char *str);
 void CDECL ShowInfoF(const char *str, ...);
 
-#ifdef DEBUG_DUMP_COMMANDS
-	void CDECL DebugDumpCommands(const char *s, ...);
-#else /* DEBUG_DUMP_COMMANDS */
-	/* when defined as an empty function with variable argument list,
-	 * it can't be inlined - so define it as an empty macro */
-	#if defined(__GNUC__) && (__GNUC__ < 3)
-		#define DebugDumpCommands(s, args...)
-	#else
-		#define DebugDumpCommands(s, ...)
-	#endif
-#endif /* DEBUG_DUMP_COMMANDS */
-
 #endif /* DEBUG_H */

src/genworld.cpp

@@ -26,6 +26,7 @@
 #include "newgrf_storage.h"
 #include "water.h"
 #include "tilehighlight_func.h"
+#include "saveload.h"
 
 #include "table/sprites.h"
 
@@ -163,8 +164,14 @@ static void _GenerateWorld(void *arg)
 		MarkWholeScreenDirty();
 
 		if (_network_dedicated) DEBUG(net, 0, "Map generated, starting game");
+		DEBUG(desync, 1, "new_map: %i\n", _settings_game.game_creation.generation_seed);
 
 		if (_settings_client.gui.pause_on_newgame && _game_mode == GM_NORMAL) DoCommandP(0, 1, 0, CMD_PAUSE);
+		if (_debug_desync_level > 0) {
+			char name[MAX_PATH];
+			snprintf(name, lengthof(name), "dmp_cmds_%08x_%08x.sav", _settings_game.game_creation.generation_seed, _date);
+			SaveOrLoad(name, SL_SAVE, AUTOSAVE_DIR);
+		}
 	} catch (...) {
 		_generating_world = false;
 		throw;

src/network/network.cpp

@@ -213,7 +213,7 @@ void NetworkTextMessage(NetworkAction action, ConsoleColour color, bool self_sen
 	SetDParam(2, data);
 	GetString(message, strid, lastof(message));
 
-	DebugDumpCommands("ddc:cmsg:%d;%d;%s\n", _date, _date_fract, message);
+	DEBUG(desync, 1, "msg: %d; %d; %s\n", _date, _date_fract, message);
 	IConsolePrintF(color, "%s", message);
 	NetworkAddChatMessage(color, duration, "%s", message);
 }
@@ -964,7 +964,7 @@ static bool NetworkDoClientLoop()
 			if (_sync_seed_1 != _random.state[0]) {
 #endif
 				NetworkError(STR_NETWORK_ERR_DESYNC);
-				DebugDumpCommands("ddc:serr:%d;%d\n", _date, _date_fract);
+				DEBUG(desync, 1, "sync_err: %d; %d\n", _date, _date_fract);
 				DEBUG(net, 0, "Sync error detected!");
 				NetworkClientError(NETWORK_RECV_STATUS_DESYNC, GetNetworkClientSocket(0));
 				return false;
@@ -1032,10 +1032,10 @@ void NetworkGameLoop()
 
 			char buff[4096];
 			if (fgets(buff, lengthof(buff), f) == NULL) break;
-			if (strncmp(buff, "ddc:cmd:", 8) != 0) continue;
+			if (strncmp(buff, "cmd: ", 8) != 0) continue;
 			cp = MallocT<CommandPacket>(1);
 			int company;
-			sscanf(&buff[8], "%d;%d;%d;%d;%d;%d;%d;%s", &next_date, &next_date_fract, &company, &cp->tile, &cp->p1, &cp->p2, &cp->cmd, cp->text);
+			sscanf(&buff[8], "%d; %d; %d; %d; %d; %d; %d; %s", &next_date, &next_date_fract, &company, &cp->tile, &cp->p1, &cp->p2, &cp->cmd, cp->text);
 			cp->company = (CompanyID)company;
 		}
 #endif /* DEBUG_DUMP_COMMANDS */

src/network/network_data.cpp

@@ -102,8 +102,6 @@ void NetworkExecuteCommand(CommandPacket *cp)
 		cp->callback = 0;
 	}
 
-	DebugDumpCommands("ddc:cmd:%d;%d;%d;%d;%d;%d;%d;%s\n", _date, _date_fract, (int)cp->company, cp->tile, cp->p1, cp->p2, cp->cmd, cp->text);
-
 	DoCommandP(cp->tile, cp->p1, cp->p2, cp->cmd | CMD_NETWORK_COMMAND, _callback_table[cp->callback], cp->text, cp->my_cmd);
 }
 

src/openttd.cpp

@@ -1029,53 +1029,53 @@ void StateGameLoop()
 		CallWindowTickEvent();
 		NewsLoop();
 	} else {
-#ifdef DEBUG_DUMP_COMMANDS
-		Vehicle *v;
-		FOR_ALL_VEHICLES(v) {
-			if (v != v->First()) continue;
-
-			switch (v->type) {
-				case VEH_ROAD: {
-					extern byte GetRoadVehLength(const Vehicle *v);
-					if (GetRoadVehLength(v) != v->u.road.cached_veh_length) {
-						printf("cache mismatch: vehicle %i, company %i, unit number %i\n", v->index, (int)v->owner, v->unitnumber);
-					}
-				} break;
+		if (_debug_desync_level > 1) {
+			Vehicle *v;
+			FOR_ALL_VEHICLES(v) {
+				if (v != v->First()) continue;
+
+				switch (v->type) {
+					case VEH_ROAD: {
+						extern byte GetRoadVehLength(const Vehicle *v);
+						if (GetRoadVehLength(v) != v->u.road.cached_veh_length) {
+							DEBUG(desync, 2, "cache mismatch: vehicle %i, company %i, unit number %i\n", v->index, (int)v->owner, v->unitnumber);
+						}
+					} break;
 
-				case VEH_TRAIN: {
-					uint length = 0;
-					for (Vehicle *u = v; u != NULL; u = u->Next()) length++;
+					case VEH_TRAIN: {
+						uint length = 0;
+						for (Vehicle *u = v; u != NULL; u = u->Next()) length++;
 
-					VehicleRail *wagons = MallocT<VehicleRail>(length);
-					length = 0;
-					for (Vehicle *u = v; u != NULL; u = u->Next()) wagons[length++] = u->u.rail;
+						VehicleRail *wagons = MallocT<VehicleRail>(length);
+						length = 0;
+						for (Vehicle *u = v; u != NULL; u = u->Next()) wagons[length++] = u->u.rail;
 
-					TrainConsistChanged(v, true);
+						TrainConsistChanged(v, true);
 
-					length = 0;
-					for (Vehicle *u = v; u != NULL; u = u->Next()) {
-						if (memcmp(&wagons[length], &u->u.rail, sizeof(VehicleRail)) != 0) {
-							printf("cache mismatch: vehicle %i, company %i, unit number %i, wagon %i\n", v->index, (int)v->owner, v->unitnumber, length);
+						length = 0;
+						for (Vehicle *u = v; u != NULL; u = u->Next()) {
+							if (memcmp(&wagons[length], &u->u.rail, sizeof(VehicleRail)) != 0) {
+								DEBUG(desync, 2, "cache mismatch: vehicle %i, company %i, unit number %i, wagon %i\n", v->index, (int)v->owner, v->unitnumber, length);
+							}
+							length++;
 						}
-						length++;
-					}
 
-					free(wagons);
-				} break;
+						free(wagons);
+					} break;
 
-				case VEH_AIRCRAFT: {
-					uint speed = v->u.air.cached_max_speed;
-					UpdateAircraftCache(v);
-					if (speed != v->u.air.cached_max_speed) {
-						printf("cache mismatch: vehicle %i, company %i, unit number %i\n", v->index, (int)v->owner, v->unitnumber);
-					}
-				} break;
+					case VEH_AIRCRAFT: {
+						uint speed = v->u.air.cached_max_speed;
+						UpdateAircraftCache(v);
+						if (speed != v->u.air.cached_max_speed) {
+							DEBUG(desync, 2, "cache mismatch: vehicle %i, company %i, unit number %i\n", v->index, (int)v->owner, v->unitnumber);
+						}
+					} break;
 
-				default:
-					break;
+					default:
+						break;
+				}
 			}
 		}
-#endif
 
 		/* All these actions has to be done from OWNER_NONE
 		 *  for multiplayer compatibility */

src/saveload.cpp

@@ -1687,6 +1687,7 @@ SaveOrLoadResult SaveOrLoad(const char *filename, int mode, Subdirectory sb)
 		/* General tactic is to first save the game to memory, then use an available writer
 		 * to write it to file, either in threaded mode if possible, or single-threaded */
 		if (mode == SL_SAVE) { /* SAVE game */
+			DEBUG(desync, 1, "save: %s\n", filename);
 			fmt = GetSavegameFormat("memory"); // write to memory
 
 			_sl.write_bytes = fmt->writer;
@@ -1714,7 +1715,7 @@ SaveOrLoadResult SaveOrLoad(const char *filename, int mode, Subdirectory sb)
 			}
 		} else { /* LOAD game */
 			assert(mode == SL_LOAD);
-			DebugDumpCommands("ddc:load:%s\n", filename);
+			DEBUG(desync, 1, "load: %s\n", filename);
 
 			if (fread(hdr, sizeof(hdr), 1, _sl.fh) != 1) SlError(STR_GAME_SAVELOAD_ERROR_FILE_NOT_READABLE);