(svn r10462) -Add: a command dumper/loader that could be enabled compile-time and server side only to aid debugging some desyncs, i.e. dump the stream of commands so it could be replayed in exactly the same way later. This should primarily be used to make desyncs more easily reproducable, so it can be properly debugged.
authorrubidium
Sat, 07 Jul 2007 10:06:10 +0000
changeset 7683 cd00f3932777
parent 7682 263dbeceba12
child 7684 02f927dceba5
(svn r10462) -Add: a command dumper/loader that could be enabled compile-time and server side only to aid debugging some desyncs, i.e. dump the stream of commands so it could be replayed in exactly the same way later. This should primarily be used to make desyncs more easily reproducable, so it can be properly debugged.
src/date.cpp
src/network/network.cpp
src/network/network.h
src/network/network_data.cpp
src/saveload.cpp
--- a/src/date.cpp	Sat Jul 07 08:53:19 2007 +0000
+++ b/src/date.cpp	Sat Jul 07 10:06:10 2007 +0000
@@ -13,6 +13,9 @@
 #include "network/network_server.h"
 #include "functions.h"
 #include "currency.h"
+#ifdef DEBUG_DUMP_COMMANDS
+#include "saveload.h"
+#endif
 
 Year      _cur_year;
 Month     _cur_month;
@@ -259,6 +262,12 @@
 
 	/* 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);
+		debug_dump_commands("ddc:save:%s\n", name);
+#endif /* DUMP_COMMANDS */
 		if (_opt.autosave != 0 && (_cur_month % _autosave_months[_opt.autosave]) == 0) {
 			_do_autosave = true;
 			RedrawAutosave();
--- a/src/network/network.cpp	Sat Jul 07 08:53:19 2007 +0000
+++ b/src/network/network.cpp	Sat Jul 07 10:06:10 2007 +0000
@@ -37,6 +37,7 @@
 #include "../console.h" /* IConsoleCmdExec */
 #include <stdarg.h> /* va_list */
 #include "../md5.h"
+#include "../fileio.h"
 
 /* Check whether NETWORK_NUM_LANDSCAPES is still in sync with NUM_LANDSCAPE */
 assert_compile((int)NETWORK_NUM_LANDSCAPES == (int)NUM_LANDSCAPE);
@@ -195,6 +196,9 @@
 			break;
 	}
 
+#ifdef DEBUG_DUMP_COMMANDS
+	debug_dump_commands("ddc:cmsg:%d;%d;%s\n", _date, _date_fract, message);
+#endif /* DUMP_COMMANDS */
 	IConsolePrintF(color, "%s", message);
 	AddTextMessage(color, duration, "%s", message);
 }
@@ -1235,6 +1239,9 @@
 			if (_sync_seed_1 != _random_seeds[0][0]) {
 #endif
 				NetworkError(STR_NETWORK_ERR_DESYNC);
+#ifdef DEBUG_DUMP_COMMANDS
+				debug_dump_commands("ddc:serr:%d;%d\n", _date, _date_fract);
+#endif /* DUMP_COMMANDS */
 				DEBUG(net, 0, "Sync error detected!");
 				NetworkClientError(NETWORK_RECV_STATUS_DESYNC, DEREF_CLIENT(0));
 				return false;
@@ -1280,6 +1287,37 @@
 	if (!NetworkReceive()) return;
 
 	if (_network_server) {
+#ifdef DEBUG_DUMP_COMMANDS
+		static FILE *f = FioFOpenFile("commands.log", "rb", SAVE_DIR);
+		static Date next_date = 0;
+		static uint32 next_date_fract;
+		static CommandPacket *cp = NULL;
+		if (f == NULL && next_date == 0) {
+			printf("Cannot open commands.log\n");
+			next_date = 1;
+		}
+
+		while (f != NULL && !feof(f)) {
+			if (cp != NULL && _date == next_date && _date_fract == next_date_fract) {
+				_current_player = cp->player;
+				_cmd_text = cp->text;
+				DoCommandP(cp->tile, cp->p1, cp->p2, NULL, cp->cmd);
+				free(cp);
+				cp = NULL;
+			}
+
+			if (cp != NULL) break;
+
+			char buff[4096];
+			if (fgets(buff, lengthof(buff), f) == NULL) break;
+			if (strncmp(buff, "ddc:cmd:", 8) != 0) continue;
+			cp = MallocT<CommandPacket>(1);
+			int player;
+			sscanf(&buff[8], "%d;%d;%d;%d;%d;%d;%d;%s", &next_date, &next_date_fract, &player, &cp->tile, &cp->p1, &cp->p2, &cp->cmd, cp->text);
+			cp->player = (Owner)player;
+		}
+#endif /* DUMP_COMMANDS */
+
 		bool send_frame = false;
 
 		// We first increase the _frame_counter
@@ -1436,4 +1474,18 @@
 			strncmp(_openttd_revision, other, NETWORK_REVISION_LENGTH - 1) == 0;
 }
 
+#ifdef DEBUG_DUMP_COMMANDS
+void CDECL debug_dump_commands(const char *s, ...)
+{
+	static FILE *f = FioFOpenFile("commands-out.log", "wb", SAVE_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 */
 #endif /* ENABLE_NETWORK */
--- a/src/network/network.h	Sat Jul 07 08:53:19 2007 +0000
+++ b/src/network/network.h	Sat Jul 07 10:06:10 2007 +0000
@@ -20,6 +20,17 @@
 //  nothing will happen.
 //#define ENABLE_NETWORK_SYNC_EVERY_FRAME
 
+/*
+ * Dumps all commands that are sent/received to stderr and saves every month.
+ * This log can become quite large over time; say in the order of two to three
+ * times the bandwidth used for network games.
+ */
+//#define DEBUG_DUMP_COMMANDS
+
+#ifdef DEBUG_DUMP_COMMANDS
+void CDECL debug_dump_commands(const char *s, ...);
+#endif /* DEBUG_DUMP_COMMANDS */
+
 // In theory sending 1 of the 2 seeds is enough to check for desyncs
 //   so in theory, this next define can be left off.
 //#define NETWORK_SEND_DOUBLE_SEED
--- a/src/network/network_data.cpp	Sat Jul 07 08:53:19 2007 +0000
+++ b/src/network/network_data.cpp	Sat Jul 07 10:06:10 2007 +0000
@@ -97,6 +97,11 @@
 		DEBUG(net, 0, "Received out-of-bounds callback (%d)", cp->callback);
 		cp->callback = 0;
 	}
+
+#ifdef DEBUG_DUMP_COMMANDS
+	debug_dump_commands("ddc:cmd:%d;%d;%d;%d;%d;%d;%d;%s\n", _date, _date_fract, (int)cp->player, cp->tile, cp->p1, cp->p2, cp->cmd, cp->text);
+#endif /* DUMP_COMMANDS */
+
 	DoCommandP(cp->tile, cp->p1, cp->p2, _callback_table[cp->callback], cp->cmd | CMD_NETWORK_COMMAND);
 }
 
--- a/src/saveload.cpp	Sat Jul 07 08:53:19 2007 +0000
+++ b/src/saveload.cpp	Sat Jul 07 10:06:10 2007 +0000
@@ -1677,6 +1677,9 @@
 		}
 	} else { /* LOAD game */
 		assert(mode == SL_LOAD);
+#ifdef DEBUG_DUMP_COMMANDS
+		debug_dump_commands("ddc:load:%s\n", filename);
+#endif /* DUMP_COMMANDS */
 
 		if (fread(hdr, sizeof(hdr), 1, _sl.fh) != 1) SlError(STR_GAME_SAVELOAD_ERROR_FILE_NOT_READABLE);