From 4689113553ad62147dfcb7ea162ef9c979888944 Mon Sep 17 00:00:00 2001 From: Jonathan G Rennison Date: Tue, 19 Dec 2023 17:55:57 +0000 Subject: [PATCH] Debug: De-duplicate formatting of hex dates for desync/random logging --- src/command.cpp | 10 +++++----- src/company_cmd.cpp | 6 +++--- src/core/checksum_func.hpp | 4 ++-- src/core/random_func.cpp | 2 +- src/date.cpp | 6 ++++++ src/date_func.h | 9 +++++++++ src/economy.cpp | 2 +- src/network/network.cpp | 14 +++++++------- src/network/network_client.cpp | 4 ++-- src/network/network_server.cpp | 4 ++-- src/sl/saveload.cpp | 2 +- 11 files changed, 39 insertions(+), 24 deletions(-) diff --git a/src/command.cpp b/src/command.cpp index 120c781acb..4fa5c4eb46 100644 --- a/src/command.cpp +++ b/src/command.cpp @@ -1173,7 +1173,7 @@ CommandCost DoCommandPInternal(TileIndex tile, uint32 p1, uint32 p2, uint64 p3, if (!random_state.Check()) { std::string msg = stdstr_fmt("Random seed changed in test command: company: %02x; tile: %06x (%u x %u); p1: %08x; p2: %08x; p3: " OTTD_PRINTFHEX64PAD "; cmd: %08x; \"%s\"%s (%s)", (int)_current_company, tile, TileX(tile), TileY(tile), p1, p2, p3, cmd & ~CMD_NETWORK_COMMAND, text, aux_data != nullptr ? ", aux data present" : "", GetCommandName(cmd)); - DEBUG(desync, 0, "msg: date{%08x; %02x; %02x}; %s", _date.base(), _date_fract, _tick_skip_counter, msg.c_str()); + DEBUG(desync, 0, "msg: %s; %s", debug_date_dumper().HexDate(), msg.c_str()); LogDesyncMsg(std::move(msg)); } @@ -1190,8 +1190,8 @@ CommandCost DoCommandPInternal(TileIndex tile, uint32 p1, uint32 p2, uint64 p3, 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}; company: %02x; tile: %06x (%u x %u); p1: %08x; p2: %08x; p3: " OTTD_PRINTFHEX64PAD "; cmd: %08x; \"%s\"%s (%s)", - _date.base(), _date_fract, _tick_skip_counter, (int)_current_company, tile, TileX(tile), TileY(tile), p1, p2, p3, cmd & ~CMD_NETWORK_COMMAND, text, aux_data != nullptr ? ", aux data present" : "", GetCommandName(cmd)); + DEBUG(desync, 1, "cmdf: %s; company: %02x; tile: %06x (%u x %u); p1: %08x; p2: %08x; p3: " OTTD_PRINTFHEX64PAD "; cmd: %08x; \"%s\"%s (%s)", + debug_date_dumper().HexDate(), (int)_current_company, tile, TileX(tile), TileY(tile), p1, p2, p3, cmd & ~CMD_NETWORK_COMMAND, text, aux_data != nullptr ? ", aux data present" : "", GetCommandName(cmd)); } cur_company.Restore(); return_dcpi(res); @@ -1211,8 +1211,8 @@ CommandCost DoCommandPInternal(TileIndex tile, uint32 p1, uint32 p2, uint64 p3, * reset the storages as we've not executed the command. */ return_dcpi(CommandCost()); } - DEBUG(desync, 1, "cmd: date{%08x; %02x; %02x}; company: %02x; tile: %06x (%u x %u); p1: %08x; p2: %08x; p3: " OTTD_PRINTFHEX64PAD "; cmd: %08x; \"%s\"%s(%s)", - _date.base(), _date_fract, _tick_skip_counter, (int)_current_company, tile, TileX(tile), TileY(tile), p1, p2, p3, cmd & ~CMD_NETWORK_COMMAND, text, aux_data != nullptr ? ", aux data present" : "", GetCommandName(cmd)); + DEBUG(desync, 1, "cmd: %s; company: %02x; tile: %06x (%u x %u); p1: %08x; p2: %08x; p3: " OTTD_PRINTFHEX64PAD "; cmd: %08x; \"%s\"%s(%s)", + debug_date_dumper().HexDate(), (int)_current_company, tile, TileX(tile), TileY(tile), p1, p2, p3, cmd & ~CMD_NETWORK_COMMAND, text, aux_data != nullptr ? ", aux data present" : "", 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 8253f541af..ae02a92f69 100644 --- a/src/company_cmd.cpp +++ b/src/company_cmd.cpp @@ -949,7 +949,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.base(), _date_fract, _tick_skip_counter, c->index); + DEBUG(desync, 1, "new_company: %s, company_id: %u", debug_date_dumper().HexDate(), c->index); break; } @@ -967,7 +967,7 @@ CommandCost CmdCompanyCtrl(TileIndex tile, DoCommandFlag flags, uint32 p1, uint3 Company *c = DoStartupNewCompany(DSNC_AI, company_id); if (c != nullptr) { NetworkServerNewCompany(c, nullptr); - DEBUG(desync, 1, "new_company_ai: date{%08x; %02x; %02x}, company_id: %u", _date.base(), _date_fract, _tick_skip_counter, c->index); + DEBUG(desync, 1, "new_company_ai: %s, company_id: %u", debug_date_dumper().HexDate(), c->index); } break; } @@ -984,7 +984,7 @@ 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.base(), _date_fract, _tick_skip_counter, company_id, reason); + DEBUG(desync, 1, "delete_company: %s, company_id: %u, reason: %u", debug_date_dumper().HexDate(), company_id, reason); CompanyNewsInformation *cni = new CompanyNewsInformation(c); diff --git a/src/core/checksum_func.hpp b/src/core/checksum_func.hpp index 25664eedf3..a7d06db53f 100644 --- a/src/core/checksum_func.hpp +++ b/src/core/checksum_func.hpp @@ -43,8 +43,8 @@ inline bool ShouldLogUpdateStateChecksum() { return _networking && (!_network_server || (NetworkClientSocket::IsValidID(0) && NetworkClientSocket::Get(0)->status != NetworkClientSocket::STATUS_INACTIVE)); } -# define DEBUG_UPDATESTATECHECKSUM(str, ...) if (ShouldLogUpdateStateChecksum()) DEBUG(statecsum, 0, "date{%08x; %02x; %02x}; %04x; %02x; " OTTD_PRINTFHEX64PAD "; %s:%d " str, \ - _date.base(), _date_fract, _tick_skip_counter, _frame_counter, (byte)_current_company, _state_checksum.state, __FILE__, __LINE__, __VA_ARGS__); +# define DEBUG_UPDATESTATECHECKSUM(str, ...) if (ShouldLogUpdateStateChecksum()) DEBUG(statecsum, 0, "%s; %04x; %02x; " OTTD_PRINTFHEX64PAD "; %s:%d " str, \ + debug_date_dumper().HexDate(), _frame_counter, (byte)_current_company, _state_checksum.state, __FILE__, __LINE__, __VA_ARGS__); #else # define DEBUG_UPDATESTATECHECKSUM(str, ...) #endif /* RANDOM_DEBUG */ diff --git a/src/core/random_func.cpp b/src/core/random_func.cpp index 687a0a033f..33799992ce 100644 --- a/src/core/random_func.cpp +++ b/src/core/random_func.cpp @@ -72,7 +72,7 @@ void SetRandomSeed(uint32 seed) uint32 DoRandom(int line, const char *file) { if (_networking && (!_network_server || (NetworkClientSocket::IsValidID(0) && NetworkClientSocket::Get(0)->status != NetworkClientSocket::STATUS_INACTIVE))) { - DEBUG(random, 0, "date{%08x; %02x; %02x}; %04x; %02x; %s:%d", _date.base(), _date_fract, _tick_skip_counter, _frame_counter, (byte)_current_company, file, line); + DEBUG(random, 0, "%s; %04x; %02x; %s:%d", debug_date_dumper().HexDate(), _frame_counter, (byte)_current_company, file, line); } return _random.Next(); diff --git a/src/date.cpp b/src/date.cpp index c22a788880..1f4c628d12 100644 --- a/src/date.cpp +++ b/src/date.cpp @@ -368,3 +368,9 @@ void IncreaseDate() /* yes, call various yearly loops */ if (new_year) OnNewYear(); } + +const char *debug_date_dumper::HexDate(Date date, DateFract date_fract, uint8 tick_skip_counter) +{ + seprintf(this->buffer, lastof(this->buffer), "date{%08x; %02x; %02x}", date.base(), date_fract, tick_skip_counter); + return this->buffer; +} diff --git a/src/date_func.h b/src/date_func.h index d532ae900d..9e5a536868 100644 --- a/src/date_func.h +++ b/src/date_func.h @@ -100,4 +100,13 @@ static inline DateTicks NowDateTicks() return DateToDateTicks(_date, _date_fract); } +struct debug_date_dumper { + const char *HexDate(Date date, DateFract date_fract, uint8 tick_skip_counter); + + inline const char *HexDate() { return this->HexDate(_date, _date_fract, _tick_skip_counter); } + +private: + char buffer[24]; +}; + #endif /* DATE_FUNC_H */ diff --git a/src/economy.cpp b/src/economy.cpp index 67e96c25ed..ac04e178a8 100644 --- a/src/economy.cpp +++ b/src/economy.cpp @@ -2459,7 +2459,7 @@ static void DoAcquireCompany(Company *c, bool hostile_takeover) { CompanyID ci = c->index; - DEBUG(desync, 1, "buy_company: date{%08x; %02x; %02x}, buyer: %u, bought: %u", _date.base(), _date_fract, _tick_skip_counter, (uint) _current_company, (uint) ci); + DEBUG(desync, 1, "buy_company: %s, buyer: %u, bought: %u", debug_date_dumper().HexDate(), (uint) _current_company, (uint) ci); CompanyNewsInformation *cni = new CompanyNewsInformation(c, Company::Get(_current_company)); diff --git a/src/network/network.cpp b/src/network/network.cpp index a56b12b658..a7b5d60d08 100644 --- a/src/network/network.cpp +++ b/src/network/network.cpp @@ -326,7 +326,7 @@ void NetworkTextMessage(NetworkAction action, TextColour colour, bool self_send, char *msg_ptr = message + Utf8Encode(message, _current_text_dir == TD_LTR ? CHAR_TD_LRM : CHAR_TD_RLM); GetString(msg_ptr, strid, lastof(message)); - DEBUG(desync, 1, "msg: date{%08x; %02x; %02x}; %s", _date.base(), _date_fract, _tick_skip_counter, message); + DEBUG(desync, 1, "msg: %s; %s", debug_date_dumper().HexDate(), message); IConsolePrintF(colour, "%s", message); NetworkAddChatMessage(colour, _settings_client.gui.network_chat_timeout, message); } @@ -1162,7 +1162,7 @@ void NetworkGameLoop() /* We don't want to log multiple times if paused. */ static Date last_log; if (last_log != _date) { - DEBUG(desync, 2, "sync: date{%08x; %02x; %02x}; %08x; %08x", _date.base(), _date_fract, _tick_skip_counter, _random.state[0], _random.state[1]); + DEBUG(desync, 2, "sync: %s; %08x; %08x", debug_date_dumper().HexDate(), _random.state[0], _random.state[1]); last_log = _date; } } @@ -1185,15 +1185,15 @@ void NetworkGameLoop() if (_date == next_date && _date_fract == next_date_fract) { if (cp != nullptr) { NetworkSendCommand(cp->tile, cp->p1, cp->p2, cp->p3, cp->cmd & ~CMD_FLAGS_MASK, nullptr, cp->text.c_str(), cp->company, cp->aux_data); - DEBUG(net, 0, "injecting: date{%08x; %02x; %02x}; %02x; %06x; %08x; %08x; " OTTD_PRINTFHEX64PAD " %08x; \"%s\" (%x) (%s)", _date.base(), _date_fract, _tick_skip_counter, (int)_current_company, cp->tile, cp->p1, cp->p2, cp->p3, cp->cmd, cp->text.c_str(), cp->binary_length, GetCommandName(cp->cmd)); + DEBUG(net, 0, "injecting: %s; %02x; %06x; %08x; %08x; " OTTD_PRINTFHEX64PAD " %08x; \"%s\" (%x) (%s)", debug_date_dumper().HexDate(), (int)_current_company, cp->tile, cp->p1, cp->p2, cp->p3, cp->cmd, cp->text.c_str(), cp->binary_length, GetCommandName(cp->cmd)); cp.reset(); } if (check_sync_state) { if (sync_state[0] == _random.state[0] && sync_state[1] == _random.state[1]) { - DEBUG(net, 0, "sync check: date{%08x; %02x; %02x}; match", _date.base(), _date_fract, _tick_skip_counter); + DEBUG(net, 0, "sync check: %s; match", debug_date_dumper().HexDate()); } else { - DEBUG(net, 0, "sync check: date{%08x; %02x; %02x}; mismatch expected {%08x, %08x}, got {%08x, %08x}", - _date.base(), _date_fract, _tick_skip_counter, sync_state[0], sync_state[1], _random.state[0], _random.state[1]); + DEBUG(net, 0, "sync check: %s; mismatch expected {%08x, %08x}, got {%08x, %08x}", + debug_date_dumper().HexDate(), sync_state[0], sync_state[1], _random.state[0], _random.state[1]); NOT_REACHED(); } check_sync_state = false; @@ -1236,7 +1236,7 @@ void NetworkGameLoop() /* Manually insert a pause when joining; this way the client can join at the exact right time. */ int ret = sscanf(p + 6, "date{%x; %x; %x}", &next_date, &next_date_fract, &next_tick_skip_counter); assert(ret == 3); - DEBUG(net, 0, "injecting pause for join at date{%08x; %02x; %02x}; please join when paused", next_date, next_date_fract, next_tick_skip_counter); + DEBUG(net, 0, "injecting pause for join at %s; please join when paused", debug_date_dumper().HexDate(next_date, next_date_fract, next_tick_skip_counter)); cp.reset(new CommandPacket()); cp->tile = 0; cp->company = COMPANY_SPECTATOR; diff --git a/src/network/network_client.cpp b/src/network/network_client.cpp index 039ab153dc..9401355a82 100644 --- a/src/network/network_client.cpp +++ b/src/network/network_client.cpp @@ -330,8 +330,8 @@ void ClientNetworkGameSocketHandler::ClientError(NetworkRecvStatus res) if (_sync_state_checksum != _state_checksum.state) info.flags |= DesyncExtraInfo::DEIF_STATE; ShowNetworkError(STR_NETWORK_ERROR_DESYNC); - DEBUG(desync, 1, "sync_err: date{%08x; %02x; %02x} {%x, " OTTD_PRINTFHEX64 "} != {%x, " OTTD_PRINTFHEX64 "}" - , _date.base(), _date_fract, _tick_skip_counter, _sync_seed_1, _sync_state_checksum, _random.state[0], _state_checksum.state); + DEBUG(desync, 1, "sync_err: %s {%x, " OTTD_PRINTFHEX64 "} != {%x, " OTTD_PRINTFHEX64 "}", + debug_date_dumper().HexDate(), _sync_seed_1, _sync_state_checksum, _random.state[0], _state_checksum.state); DEBUG(net, 0, "Sync error detected!"); std::string desync_log; diff --git a/src/network/network_server.cpp b/src/network/network_server.cpp index e340a54ac1..8df7e2763c 100644 --- a/src/network/network_server.cpp +++ b/src/network/network_server.cpp @@ -1020,7 +1020,7 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_JOIN(Packet *p) ci->join_frame = _frame_counter; ci->client_name = client_name; ci->client_playas = playas; - DEBUG(desync, 1, "client: date{%08x; %02x; %02x}; client: %02x; company: %02x", _date.base(), _date_fract, _tick_skip_counter, (int)ci->index, (int)ci->client_playas); + DEBUG(desync, 1, "client: %s; client: %02x; company: %02x", debug_date_dumper().HexDate(), (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; @@ -1812,7 +1812,7 @@ void NetworkUpdateClientInfo(ClientID client_id) if (ci == nullptr) return; - DEBUG(desync, 1, "client: date{%08x; %02x; %02x}; client: %02x; company: %02x", _date.base(), _date_fract, _tick_skip_counter, client_id, (int)ci->client_playas); + DEBUG(desync, 1, "client: %s; client: %02x; company: %02x", debug_date_dumper().HexDate(), client_id, (int)ci->client_playas); for (NetworkClientSocket *cs : NetworkClientSocket::Iterate()) { if (cs->status >= ServerNetworkGameSocketHandler::STATUS_AUTHORIZED) { diff --git a/src/sl/saveload.cpp b/src/sl/saveload.cpp index 9e783fdb5b..a3bc8d86f8 100644 --- a/src/sl/saveload.cpp +++ b/src/sl/saveload.cpp @@ -3726,7 +3726,7 @@ SaveOrLoadResult SaveOrLoad(const std::string &filename, SaveLoadOperation fop, } if (fop == SLO_SAVE) { // SAVE game - DEBUG(desync, 1, "save: date{%08x; %02x; %02x}; %s", _date.base(), _date_fract, _tick_skip_counter, filename.c_str()); + DEBUG(desync, 1, "save: %s; %s", debug_date_dumper().HexDate(), filename.c_str()); if (!_settings_client.gui.threaded_saves) threaded = false; return DoSave(new FileWriter(fh), threaded);