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);
_______________________________________________ Mailing list: https://launchpad.net/~widelands-dev Post to : widelands-dev@lists.launchpad.net Unsubscribe : https://launchpad.net/~widelands-dev More help : https://help.launchpad.net/ListHelp