dave/openttd
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Debug: De-duplicate formatting of hex dates for desync/random logging

Browse Source
This commit is contained in:
Jonathan G Rennison
2023-12-19 17:55:57 +00:00
parent 61d65c9861
commit 4689113553
11 changed files with 39 additions and 24 deletions
Download Patch File Download Diff File Expand all files Collapse all files

10
src/command.cpp
View File

@@ -1173,7 +1173,7 @@ CommandCost DoCommandPInternal(TileIndex tile, uint32 p1, uint32 p2, uint64 p3,
if (!random_state.Check()) { 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)", 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)); (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)); 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) { if (!_networking || _generating_world || (cmd & CMD_NETWORK_COMMAND) != 0) {
/* Log the failed command as well. Just to be able to be find /* Log the failed command as well. Just to be able to be find
* causes of desyncs due to bad command test implementations. */ * 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)", DEBUG(desync, 1, "cmdf: %s; 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_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(); cur_company.Restore();
return_dcpi(res); 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. */ * reset the storages as we've not executed the command. */
return_dcpi(CommandCost()); 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)", DEBUG(desync, 1, "cmd: %s; 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_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 /* Actually try and execute the command. If no cost-type is given
* use the construction one */ * use the construction one */

6
src/company_cmd.cpp
View File

@@ -949,7 +949,7 @@ CommandCost CmdCompanyCtrl(TileIndex tile, DoCommandFlag flags, uint32 p1, uint3
} }
NetworkServerNewCompany(c, ci); 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; break;
} }
@@ -967,7 +967,7 @@ CommandCost CmdCompanyCtrl(TileIndex tile, DoCommandFlag flags, uint32 p1, uint3
Company *c = DoStartupNewCompany(DSNC_AI, company_id); Company *c = DoStartupNewCompany(DSNC_AI, company_id);
if (c != nullptr) { if (c != nullptr) {
NetworkServerNewCompany(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; break;
} }
@@ -984,7 +984,7 @@ CommandCost CmdCompanyCtrl(TileIndex tile, DoCommandFlag flags, uint32 p1, uint3
if (!(flags & DC_EXEC)) return CommandCost(); 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); CompanyNewsInformation *cni = new CompanyNewsInformation(c);

4
src/core/checksum_func.hpp
View File

@@ -43,8 +43,8 @@ inline bool ShouldLogUpdateStateChecksum()
{ {
return _networking && (!_network_server || (NetworkClientSocket::IsValidID(0) && NetworkClientSocket::Get(0)->status != NetworkClientSocket::STATUS_INACTIVE)); 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, \ # define DEBUG_UPDATESTATECHECKSUM(str, ...) if (ShouldLogUpdateStateChecksum()) DEBUG(statecsum, 0, "%s; %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__); debug_date_dumper().HexDate(), _frame_counter, (byte)_current_company, _state_checksum.state, __FILE__, __LINE__, __VA_ARGS__);
#else #else
# define DEBUG_UPDATESTATECHECKSUM(str, ...) # define DEBUG_UPDATESTATECHECKSUM(str, ...)
#endif /* RANDOM_DEBUG */ #endif /* RANDOM_DEBUG */

2
src/core/random_func.cpp
View File

@@ -72,7 +72,7 @@ void SetRandomSeed(uint32 seed)
uint32 DoRandom(int line, const char *file) uint32 DoRandom(int line, const char *file)
{ {
if (_networking && (!_network_server || (NetworkClientSocket::IsValidID(0) && NetworkClientSocket::Get(0)->status != NetworkClientSocket::STATUS_INACTIVE))) { 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(); return _random.Next();

6
src/date.cpp
View File

@@ -368,3 +368,9 @@ void IncreaseDate()
/* yes, call various yearly loops */ /* yes, call various yearly loops */
if (new_year) OnNewYear(); 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;
}

9
src/date_func.h
View File

@@ -100,4 +100,13 @@ static inline DateTicks NowDateTicks()
return DateToDateTicks(_date, _date_fract); 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 */ #endif /* DATE_FUNC_H */

2
src/economy.cpp
View File

@@ -2459,7 +2459,7 @@ static void DoAcquireCompany(Company *c, bool hostile_takeover)
{ {
CompanyID ci = c->index; 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)); CompanyNewsInformation *cni = new CompanyNewsInformation(c, Company::Get(_current_company));

14
src/network/network.cpp
View File

@@ -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); char *msg_ptr = message + Utf8Encode(message, _current_text_dir == TD_LTR ? CHAR_TD_LRM : CHAR_TD_RLM);
GetString(msg_ptr, strid, lastof(message)); 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); IConsolePrintF(colour, "%s", message);
NetworkAddChatMessage(colour, _settings_client.gui.network_chat_timeout, 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. */ /* We don't want to log multiple times if paused. */
static Date last_log; static Date last_log;
if (last_log != _date) { 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; last_log = _date;
} }
} }
@@ -1185,15 +1185,15 @@ void NetworkGameLoop()
if (_date == next_date && _date_fract == next_date_fract) { if (_date == next_date && _date_fract == next_date_fract) {
if (cp != nullptr) { 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); 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(); cp.reset();
} }
if (check_sync_state) { if (check_sync_state) {
if (sync_state[0] == _random.state[0] && sync_state[1] == _random.state[1]) { 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 { } else {
DEBUG(net, 0, "sync check: date{%08x; %02x; %02x}; mismatch expected {%08x, %08x}, got {%08x, %08x}", DEBUG(net, 0, "sync check: %s; 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_date_dumper().HexDate(), sync_state[0], sync_state[1], _random.state[0], _random.state[1]);
NOT_REACHED(); NOT_REACHED();
} }
check_sync_state = false; 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. */ /* 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); int ret = sscanf(p + 6, "date{%x; %x; %x}", &next_date, &next_date_fract, &next_tick_skip_counter);
assert(ret == 3); 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.reset(new CommandPacket());
cp->tile = 0; cp->tile = 0;
cp->company = COMPANY_SPECTATOR; cp->company = COMPANY_SPECTATOR;

4
src/network/network_client.cpp
View File

@@ -330,8 +330,8 @@ void ClientNetworkGameSocketHandler::ClientError(NetworkRecvStatus res)
if (_sync_state_checksum != _state_checksum.state) info.flags |= DesyncExtraInfo::DEIF_STATE; if (_sync_state_checksum != _state_checksum.state) info.flags |= DesyncExtraInfo::DEIF_STATE;
ShowNetworkError(STR_NETWORK_ERROR_DESYNC); ShowNetworkError(STR_NETWORK_ERROR_DESYNC);
DEBUG(desync, 1, "sync_err: date{%08x; %02x; %02x} {%x, " OTTD_PRINTFHEX64 "} != {%x, " OTTD_PRINTFHEX64 "}" DEBUG(desync, 1, "sync_err: %s {%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_date_dumper().HexDate(), _sync_seed_1, _sync_state_checksum, _random.state[0], _state_checksum.state);
DEBUG(net, 0, "Sync error detected!"); DEBUG(net, 0, "Sync error detected!");
std::string desync_log; std::string desync_log;

4
src/network/network_server.cpp
View File

@@ -1020,7 +1020,7 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_JOIN(Packet *p)
ci->join_frame = _frame_counter; ci->join_frame = _frame_counter;
ci->client_name = client_name; ci->client_name = client_name;
ci->client_playas = playas; 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 */ /* Make sure companies to which people try to join are not autocleaned */
if (Company::IsValidID(playas)) _network_company_states[playas].months_empty = 0; if (Company::IsValidID(playas)) _network_company_states[playas].months_empty = 0;
@@ -1812,7 +1812,7 @@ void NetworkUpdateClientInfo(ClientID client_id)
if (ci == nullptr) return; 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()) { for (NetworkClientSocket *cs : NetworkClientSocket::Iterate()) {
if (cs->status >= ServerNetworkGameSocketHandler::STATUS_AUTHORIZED) { if (cs->status >= ServerNetworkGameSocketHandler::STATUS_AUTHORIZED) {

2
src/sl/saveload.cpp
View File

@@ -3726,7 +3726,7 @@ SaveOrLoadResult SaveOrLoad(const std::string &filename, SaveLoadOperation fop,
} }
if (fop == SLO_SAVE) { // SAVE game 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; if (!_settings_client.gui.threaded_saves) threaded = false;
return DoSave(new FileWriter(fh), threaded); return DoSave(new FileWriter(fh), threaded);