widelands-dev team mailing list archive

[Notabilis <notabilis27@xxxxxx>]

Notabilis has proposed merging lp:~widelands-dev/widelands/bug-better-syncstreams into lp:widelands.

Commit message:
Print more information in syncstreams.

Requested reviews:
  Widelands Developers (widelands-dev)

For more details, see:
https://code.launchpad.net/~widelands-dev/widelands/bug-better-syncstreams/+merge/361922

Not ready for review and merge yet, only starting merge request for Windows builds.
-- 
Your team Widelands Developers is requested to review the proposed merge of lp:~widelands-dev/widelands/bug-better-syncstreams into lp:widelands.

=== modified file 'data/tribes/buildings/productionsites/atlanteans/mill/init.lua'
--- data/tribes/buildings/productionsites/atlanteans/mill/init.lua	2018-09-06 08:21:35 +0000
+++ data/tribes/buildings/productionsites/atlanteans/mill/init.lua	2019-01-17 19:30:44 +0000
@@ -74,7 +74,7 @@
          }
       },
       produce_blackroot_flour = {
-         -- TRANSLATORS: Completed/Skipped/Did not start grinding blackrootbecause ...
+         -- TRANSLATORS: Completed/Skipped/Did not start grinding blackroot because ...
          descname = _"grinding blackroot",
          actions = {
             -- No check whether we need blackroot_flour because blackroots cannot be used for anything else.

=== modified file 'src/economy/economy.cc'
--- src/economy/economy.cc	2018-12-13 07:24:01 +0000
+++ src/economy/economy.cc	2019-01-17 19:30:44 +0000
@@ -706,6 +706,7 @@
 		// alerts, so add info to the sync stream here.
 		{
 			::StreamWrite& ss = game.syncstream();
+			ss.unsigned_8(Syncstream::ProcessRequests);
 			ss.unsigned_8(req.get_type());
 			ss.unsigned_8(req.get_index());
 			ss.unsigned_32(req.target().serial());
@@ -1046,7 +1047,7 @@
 	// to avoid potential future problems caused by the supplies_ changing
 	// under us in some way.
 	::StreamWrite& ss = game.syncstream();
-	ss.unsigned_32(0x02decafa);  // appears as facade02 in sync stream
+	ss.unsigned_8(Syncstream::HandleActiveSupplies);
 	ss.unsigned_32(assignments.size());
 
 	for (const auto& temp_assignment : assignments) {

=== modified file 'src/economy/request.cc'
--- src/economy/request.cc	2018-12-13 07:24:01 +0000
+++ src/economy/request.cc	2019-01-17 19:30:44 +0000
@@ -380,7 +380,7 @@
 	assert(is_open());
 
 	::StreamWrite& ss = game.syncstream();
-	ss.unsigned_32(0x01decafa);  // appears as facade01 in sync stream
+	ss.unsigned_8(Syncstream::StartTransfer);
 	ss.unsigned_32(target().serial());
 	ss.unsigned_32(supp.get_position(game)->serial());
 

=== modified file 'src/logic/cmd_queue.cc'
--- src/logic/cmd_queue.cc	2018-12-13 07:24:01 +0000
+++ src/logic/cmd_queue.cc	2019-01-17 19:30:44 +0000
@@ -114,8 +114,7 @@
 
 			if (dynamic_cast<GameLogicCommand*>(&c)) {
 				StreamWrite& ss = game_.syncstream();
-				static uint8_t const tag[] = {0xde, 0xad, 0x00};
-				ss.data(tag, 3);  // provide an easy-to-find pattern as debugging aid
+				ss.unsigned_8(Syncstream::RunQueue);
 				ss.unsigned_32(c.duetime());
 				ss.unsigned_32(static_cast<uint32_t>(c.id()));
 			}

=== modified file 'src/logic/filesystem_constants.h'
--- src/logic/filesystem_constants.h	2018-11-09 08:00:35 +0000
+++ src/logic/filesystem_constants.h	2019-01-17 19:30:44 +0000
@@ -49,6 +49,7 @@
 const std::string kReplayDir = "replays";
 const std::string kReplayExtension = ".wrpl";
 const std::string kSyncstreamExtension = ".wss";
+const std::string kSyncstreamExcerptExtension = ".wse";
 // The time in seconds for how long old replays/syncstreams should be kept
 // around, in seconds. Right now this is 4 weeks.
 constexpr double kReplayKeepAroundTime = 4 * 7 * 24 * 60 * 60;

=== modified file 'src/logic/game.cc'
--- src/logic/game.cc	2018-12-13 07:24:01 +0000
+++ src/logic/game.cc	2019-01-17 19:30:44 +0000
@@ -87,6 +87,8 @@
 void Game::SyncWrapper::start_dump(const std::string& fname) {
 	dumpfname_ = fname + kSyncstreamExtension;
 	dump_.reset(g_fs->open_stream_write(dumpfname_));
+	current_excerpt_id_ = 0;
+	excerpts_buffer_[current_excerpt_id_].clear();
 }
 
 void Game::SyncWrapper::data(void const* const sync_data, size_t const size) {
@@ -114,6 +116,8 @@
 			log("Writing to syncstream file %s failed. Stop synctream dump.\n", dumpfname_.c_str());
 			dump_.reset();
 		}
+		assert(current_excerpt_id_ < kExcerptSize);
+		excerpts_buffer_[current_excerpt_id_].append(static_cast<const char*>(sync_data), size);
 	}
 
 	target_.data(sync_data, size);
@@ -603,6 +607,40 @@
 }
 
 /**
+ * Switches to the next part of the syncstream excerpt.
+ */
+void Game::report_sync_request() {
+	syncwrapper_.current_excerpt_id_ = (syncwrapper_.current_excerpt_id_ + 1) % SyncWrapper::kExcerptSize;
+	syncwrapper_.excerpts_buffer_[syncwrapper_.current_excerpt_id_].clear();
+}
+
+/**
+ * Triggers writing of syncstream excerpt and adds the playernumber of the desynced player
+ * to the stream.
+ */
+void Game::report_desync(uint32_t playernumber) {
+	std::string filename = syncwrapper_.dumpfname_;
+	filename.replace(filename.length() - kSyncstreamExtension.length(), kSyncstreamExtension.length(), kSyncstreamExcerptExtension);
+	std::unique_ptr<StreamWrite> file(g_fs->open_stream_write(filename));
+	assert(file != nullptr);
+	// Write our buffers to the file. Start with the oldest one
+	const size_t i2 = (syncwrapper_.current_excerpt_id_ + 1) % SyncWrapper::kExcerptSize;
+	size_t i = i2;
+	for (;;) {
+		file->text(syncwrapper_.excerpts_buffer_[i]);
+		syncwrapper_.excerpts_buffer_[i].clear();
+		i = (i + 1) % SyncWrapper::kExcerptSize;
+		if (i == i2) {
+			break;
+		}
+	}
+	file->unsigned_8(Syncstream::Desync);
+	file->unsigned_32(playernumber);
+	// Restart buffers
+	syncwrapper_.current_excerpt_id_ = 0;
+}
+
+/**
  * Calculate the current synchronization checksum and copy
  * it into the given array, without affecting the subsequent
  * checksumming process.
@@ -624,6 +662,7 @@
  */
 uint32_t Game::logic_rand() {
 	uint32_t const result = rng().rand();
+	syncstream().unsigned_8(Syncstream::Random);
 	syncstream().unsigned_32(result);
 	return result;
 }

=== modified file 'src/logic/game.h'
--- src/logic/game.h	2018-12-13 07:24:01 +0000
+++ src/logic/game.h	2019-01-17 19:30:44 +0000
@@ -63,6 +63,51 @@
 	gs_ending
 };
 
+// The entry types that are written to the syncstream
+// The IDs are a number in the higher 4 bits and the length in bytes in the lower 4 bits
+namespace Syncstream {
+	// game.cc Game::report_desync()
+	// u32 id of desynced user
+	constexpr uint8_t Desync = 0x14;
+	// map_object.cc CmdDestroyMapObject::execute()
+	// u32 object serial
+	constexpr uint8_t DestroyObject = 0x24;
+	// economy.cc Economy::process_requests()
+	// u8 request type
+	// u8 request index
+	// u32 target serial
+	constexpr uint8_t ProcessRequests = 0x36;
+	// economy.cc Economy::handle_active_supplies()
+	// u32 assignments size
+	constexpr uint8_t HandleActiveSupplies = 0x44;
+	// request.cc Request::start_transfer()
+	// u32 target serial
+	// u32 source(?) serial
+	constexpr uint8_t StartTransfer = 0x58;
+	// cmd_queue.cc CmdQueue::run_queue()
+	// u32 duetime
+	// u32 command id
+	constexpr uint8_t RunQueue = 0x68;
+	// game.h Game::logic_rand_seed()
+	// u32 random seed
+	constexpr uint8_t RandomSeed = 0x74;
+	// game.cc Game::logic_rand()
+	// u32 random value
+	constexpr uint8_t Random = 0x84;
+	// map_object.cc CmdAct::execute()
+	// u32 object serial
+	constexpr uint8_t CmdAct = 0x94;
+	// battle.cc Battle::Battle()
+	// u32 first soldier serial
+	// u32 second soldier serial
+	constexpr uint8_t Battle = 0xA8;
+	// bob.cc Bob::set_position()
+	// u32 bob serial
+	// s16 position x
+	// s16 position y
+	constexpr uint8_t BobSetPosition = 0xB8;
+}
+
 class Player;
 class MapLoader;
 class PlayerCommand;
@@ -187,9 +232,13 @@
 
 	void logic_rand_seed(uint32_t const seed) {
 		rng().seed(seed);
+		syncstream().unsigned_8(Syncstream::RandomSeed);
+		syncstream().unsigned_32(seed);
 	}
 
 	StreamWrite& syncstream();
+	void report_sync_request();
+	void report_desync(uint32_t playernumber);
 	Md5Checksum get_sync_hash() const;
 
 	void enqueue_command(Command* const);
@@ -279,7 +328,8 @@
 		     target_(target),
 		     counter_(0),
 		     next_diskspacecheck_(0),
-		     syncstreamsave_(false) {
+		     syncstreamsave_(false),
+		     current_excerpt_id_(0) {
 		}
 
 		~SyncWrapper() override;
@@ -304,6 +354,17 @@
 		std::unique_ptr<StreamWrite> dump_;
 		std::string dumpfname_;
 		bool syncstreamsave_;
+		// Use a cyclic buffer for storing parts of the syncstream
+		// Currently used buffer
+		size_t current_excerpt_id_;
+		// (Arbitrary) count of buffers
+		// Syncreports seem to be requested from the network clients every game second so this
+		// buffer should be big enough to store the last 32 seconds of the game actions leading
+		// up to the desync
+		static constexpr size_t kExcerptSize = 32;
+		// Array of byte buffers
+		// std::string is used as a binary buffer here
+		std::string excerpts_buffer_[kExcerptSize];
 	} syncwrapper_;
 
 	GameController* ctrl_;

=== modified file 'src/logic/map_objects/bob.cc'
--- src/logic/map_objects/bob.cc	2018-12-13 07:24:01 +0000
+++ src/logic/map_objects/bob.cc	2019-01-17 19:30:44 +0000
@@ -893,6 +893,7 @@
 	// randomly generated movements.
 	if (upcast(Game, game, &egbase)) {
 		StreamWrite& ss = game->syncstream();
+		ss.unsigned_8(Syncstream::BobSetPosition);
 		ss.unsigned_32(serial());
 		ss.signed_16(coords.x);
 		ss.signed_16(coords.y);

=== modified file 'src/logic/map_objects/map_object.cc'
--- src/logic/map_objects/map_object.cc	2018-12-13 07:24:01 +0000
+++ src/logic/map_objects/map_object.cc	2019-01-17 19:30:44 +0000
@@ -49,6 +49,7 @@
 }
 
 void CmdDestroyMapObject::execute(Game& game) {
+	game.syncstream().unsigned_8(Syncstream::DestroyObject);
 	game.syncstream().unsigned_32(obj_serial);
 
 	if (MapObject* obj = game.objects().get_object(obj_serial))
@@ -94,6 +95,7 @@
 }
 
 void CmdAct::execute(Game& game) {
+	game.syncstream().unsigned_8(Syncstream::CmdAct);
 	game.syncstream().unsigned_32(obj_serial);
 
 	if (MapObject* const obj = game.objects().get_object(obj_serial))

=== modified file 'src/logic/map_objects/tribes/battle.cc'
--- src/logic/map_objects/tribes/battle.cc	2018-12-13 07:24:01 +0000
+++ src/logic/map_objects/tribes/battle.cc	2019-01-17 19:30:44 +0000
@@ -65,7 +65,7 @@
 	assert(first_soldier->get_owner() != second_soldier->get_owner());
 	{
 		StreamWrite& ss = game.syncstream();
-		ss.unsigned_32(0x00e111ba);  // appears as ba111e00 in a hexdump
+		ss.unsigned_8(Syncstream::Battle);
 		ss.unsigned_32(first_soldier->serial());
 		ss.unsigned_32(second_soldier->serial());
 	}

=== modified file 'src/network/gameclient.cc'
--- src/network/gameclient.cc	2018-12-13 07:24:01 +0000
+++ src/network/gameclient.cc	2019-01-17 19:30:44 +0000
@@ -860,6 +860,7 @@
 		int32_t const time = packet.signed_32();
 		d->time.receive(time);
 		d->game->enqueue_command(new CmdNetCheckSync(time, [this] { sync_report_callback(); }));
+		d->game->report_sync_request();
 		break;
 	}
 
@@ -891,8 +892,11 @@
 	case NETCMD_INFO_DESYNC:
 		log("[Client] received NETCMD_INFO_DESYNC. Trying to salvage some "
 		    "information for debugging.\n");
-		if (d->game)
+		if (d->game) {
 			d->game->save_syncstream(true);
+			// We don't know our playernumber, just use 0
+			d->game->report_desync(0);
+		}
 		break;
 
 	default:

=== modified file 'src/network/gamehost.cc'
--- src/network/gamehost.cc	2018-12-13 07:24:01 +0000
+++ src/network/gamehost.cc	2019-01-17 19:30:44 +0000
@@ -1865,6 +1865,7 @@
 	}
 
 	log("[Host]: Requesting sync reports for time %i\n", d->syncreport_time);
+	d->game->report_sync_request();
 
 	SendPacket packet;
 	packet.unsigned_8(NETCMD_SYNCREQUEST);
@@ -1906,6 +1907,8 @@
 			    i, d->syncreport.str().c_str(), client.syncreport.str().c_str());
 
 			d->game->save_syncstream(true);
+			// Create syncstream excerpt and add faulting player number
+			d->game->report_desync(i);
 
 			SendPacket packet;
 			packet.unsigned_8(NETCMD_INFO_DESYNC);