From 002f5ca70e6c3ddeca64a8cbf7e4bcd99de9ca94 Mon Sep 17 00:00:00 2001 From: Jonathan G Rennison Date: Mon, 20 May 2019 19:38:47 +0100 Subject: [PATCH] Adjust desync log format and add company events to log --- src/command.cpp | 6 ++++-- src/company_cmd.cpp | 8 +++++++- src/economy.cpp | 2 ++ src/network/network.cpp | 6 ++++-- src/network/network_server.cpp | 4 ++-- 5 files changed, 19 insertions(+), 7 deletions(-) diff --git a/src/command.cpp b/src/command.cpp index bd989405dd..23f7f31046 100644 --- a/src/command.cpp +++ b/src/command.cpp @@ -942,7 +942,8 @@ CommandCost DoCommandPInternal(TileIndex tile, uint32 p1, uint32 p2, uint32 cmd, if (!_networking || _generating_world || (cmd & CMD_NETWORK_COMMAND) != 0) { /* Log the failed command as well. Just to be able to be find * causes of desyncs due to bad command test implementations. */ - DEBUG(desync, 1, "cmdf: date{%08x; %02x; %02x}; %02X; %06x; %08x; %08x; %08x; \"%s\" (%s)", _date, _date_fract, _tick_skip_counter, (int)_current_company, tile, p1, p2, cmd & ~CMD_NETWORK_COMMAND, text, GetCommandName(cmd)); + DEBUG(desync, 1, "cmdf: date{%08x; %02x; %02x}; company: %02x; tile: %06x (%u x %u); p1: %08x; p2: %08x; cmd: %08x; \"%s\" %X (%s)", + _date, _date_fract, _tick_skip_counter, (int)_current_company, tile, TileX(tile), TileY(tile), p1, p2, cmd & ~CMD_NETWORK_COMMAND, text, binary_length, GetCommandName(cmd)); } cur_company.Restore(); return_dcpi(res); @@ -962,7 +963,8 @@ CommandCost DoCommandPInternal(TileIndex tile, uint32 p1, uint32 p2, uint32 cmd, * reset the storages as we've not executed the command. */ return_dcpi(CommandCost()); } - DEBUG(desync, 1, "cmd: date{%08x; %02x; %02x}; %02x; %06x; %08x; %08x; %08x; \"%s\" (%s)", _date, _date_fract, _tick_skip_counter, (int)_current_company, tile, p1, p2, cmd & ~CMD_NETWORK_COMMAND, text, GetCommandName(cmd)); + DEBUG(desync, 1, "cmd: date{%08x; %02x; %02x}; company: %02x; tile: %06x (%u x %u); p1: %08x; p2: %08x; cmd: %08x; \"%s\" %X (%s)", + _date, _date_fract, _tick_skip_counter, (int)_current_company, tile, TileX(tile), TileY(tile), p1, p2, cmd & ~CMD_NETWORK_COMMAND, text, binary_length, GetCommandName(cmd)); /* Actually try and execute the command. If no cost-type is given * use the construction one */ diff --git a/src/company_cmd.cpp b/src/company_cmd.cpp index 153bb59852..fdd404900e 100644 --- a/src/company_cmd.cpp +++ b/src/company_cmd.cpp @@ -874,6 +874,7 @@ CommandCost CmdCompanyCtrl(TileIndex tile, DoCommandFlag flags, uint32 p1, uint3 } NetworkServerNewCompany(c, ci); + DEBUG(desync, 1, "new_company: date{%08x; %02x; %02x}, company_id: %u", _date, _date_fract, _tick_skip_counter, c->index); break; } @@ -882,7 +883,10 @@ CommandCost CmdCompanyCtrl(TileIndex tile, DoCommandFlag flags, uint32 p1, uint3 if (company_id != INVALID_COMPANY && (company_id >= MAX_COMPANIES || Company::IsValidID(company_id))) return CMD_ERROR; Company *c = DoStartupNewCompany(true, company_id); - if (c != nullptr) NetworkServerNewCompany(c, nullptr); + if (c != nullptr) { + NetworkServerNewCompany(c, nullptr); + DEBUG(desync, 1, "new_company_ai: date{%08x; %02x; %02x}, company_id: %u", _date, _date_fract, _tick_skip_counter, c->index); + } break; } @@ -895,6 +899,8 @@ CommandCost CmdCompanyCtrl(TileIndex tile, DoCommandFlag flags, uint32 p1, uint3 if (!(flags & DC_EXEC)) return CommandCost(); + DEBUG(desync, 1, "delete_company: date{%08x; %02x; %02x}, company_id: %u, reason: %u", _date, _date_fract, _tick_skip_counter, company_id, reason); + /* Delete any open window of the company */ DeleteCompanyWindows(c->index); CompanyNewsInformation *cni = MallocT(1); diff --git a/src/economy.cpp b/src/economy.cpp index dfa27bbabc..177dadf47d 100644 --- a/src/economy.cpp +++ b/src/economy.cpp @@ -2205,6 +2205,8 @@ static void DoAcquireCompany(Company *c) { CompanyID ci = c->index; + DEBUG(desync, 1, "buy_company: date{%08x; %02x; %02x}, buyer: %u, bought: %u", _date, _date_fract, _tick_skip_counter, (uint) _current_company, (uint) ci); + CompanyNewsInformation *cni = MallocT(1); cni->FillData(c, Company::Get(_current_company)); diff --git a/src/network/network.cpp b/src/network/network.cpp index ffd118cbab..8c7f4e6ce9 100644 --- a/src/network/network.cpp +++ b/src/network/network.cpp @@ -954,7 +954,7 @@ void NetworkGameLoop() cp.reset(new CommandPacket()); int company; cp->text.resize(MAX_CMD_TEXT_LENGTH); - int ret = sscanf(p, "date{%x; %x; %x}; %x; %x; %x; %x; %x; \"%[^\"]\"", &next_date, &next_date_fract, &next_tick_skip_counter, &company, &cp->tile, &cp->p1, &cp->p2, &cp->cmd, const_cast(cp->text.c_str())); + int ret = sscanf(p, "date{%x; %x; %x}; company: %x; tile: %x (%*u x %*u); p1: %x; p2: %x; cmd: %x; \"%[^\"]\"", &next_date, &next_date_fract, &next_tick_skip_counter, &company, &cp->tile, &cp->p1, &cp->p2, &cp->cmd, const_cast(cp->text.c_str())); /* There are 9 pieces of data to read, however the last is a * string that might or might not exist. Ignore it if that * string misses because in 99% of the time it's not used. */ @@ -980,7 +980,9 @@ void NetworkGameLoop() assert(ret == 5); check_sync_state = true; } else if (strncmp(p, "msg: ", 5) == 0 || strncmp(p, "client: ", 8) == 0 || - strncmp(p, "load: ", 6) == 0 || strncmp(p, "save: ", 6) == 0) { + strncmp(p, "load: ", 6) == 0 || strncmp(p, "save: ", 6) == 0 || + strncmp(p, "new_company: ", 13) == 0 || strncmp(p, "new_company_ai: ", 16) == 0 || + strncmp(p, "buy_company: ", 13) == 0 || strncmp(p, "delete_company: ", 16) == 0) { /* A message that is not very important to the log playback, but part of the log. */ #ifndef DEBUG_FAILED_DUMP_COMMANDS } else if (strncmp(p, "cmdf: ", 6) == 0) { diff --git a/src/network/network_server.cpp b/src/network/network_server.cpp index 101c768e81..407583a1a1 100644 --- a/src/network/network_server.cpp +++ b/src/network/network_server.cpp @@ -944,7 +944,7 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_JOIN(Packet *p) strecpy(ci->client_name, name, lastof(ci->client_name)); ci->client_playas = playas; ci->client_lang = client_lang; - DEBUG(desync, 1, "client: date{%08x; %02x; %02x}; %02x; %02x", _date, _date_fract, _tick_skip_counter, (int)ci->client_playas, (int)ci->index); + DEBUG(desync, 1, "client: date{%08x; %02x; %02x}; client: %02x; company: %02x", _date, _date_fract, _tick_skip_counter, (int)ci->index, (int)ci->client_playas); /* Make sure companies to which people try to join are not autocleaned */ if (Company::IsValidID(playas)) _network_company_states[playas].months_empty = 0; @@ -1608,7 +1608,7 @@ void NetworkUpdateClientInfo(ClientID client_id) if (ci == nullptr) return; - DEBUG(desync, 1, "client: date{%08x; %02x; %02x}; %02x; %04x", _date, _date_fract, _tick_skip_counter, (int)ci->client_playas, client_id); + DEBUG(desync, 1, "client: date{%08x; %02x; %02x}; client: %02x; company: %02x", _date, _date_fract, _tick_skip_counter, client_id, (int)ci->client_playas); FOR_ALL_CLIENT_SOCKETS(cs) { cs->SendClientInfo(ci);