Include tick skip counter in all desync debug output.

Change message format to make field identification easier.
Update desync message reader to support tick skip counter.
pull/8/head
Jonathan G Rennison 8 years ago
parent 489e6aced6
commit 8e6569c11f

@ -778,7 +778,7 @@ 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: %08x; %02x; %02x; %06x; %08x; %08x; %08x; \"%s\" (%s)", _date, _date_fract, (int)_current_company, tile, p1, p2, cmd & ~CMD_NETWORK_COMMAND, text, GetCommandName(cmd));
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));
}
cur_company.Restore();
return_dcpi(res);
@ -800,7 +800,7 @@ CommandCost DoCommandPInternal(TileIndex tile, uint32 p1, uint32 p2, uint32 cmd,
return_dcpi(CommandCost());
}
#endif /* ENABLE_NETWORK */
DEBUG(desync, 1, "cmd: %08x; %02x; %02x; %06x; %08x; %08x; %08x; \"%s\" (%s)", _date, _date_fract, (int)_current_company, tile, p1, p2, cmd & ~CMD_NETWORK_COMMAND, text, GetCommandName(cmd));
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));
/* Actually try and execute the command. If no cost-type is given
* use the construction one */

@ -74,7 +74,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, "%08x; %02x; %02X; %04x; %02x; %s:%d", _date, _date_fract, _tick_skip_counter, _frame_counter, (byte)_current_company, file, line);
DEBUG(random, 0, "date{%08x; %02x; %02x}; %04x; %02x; %s:%d", _date, _date_fract, _tick_skip_counter, _frame_counter, (byte)_current_company, file, line);
}
return _random.Next();

@ -275,7 +275,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: %08x; %02x; %s", _date, _date_fract, message);
DEBUG(desync, 1, "msg: date{%08x; %02x; %02x}; %s", _date, _date_fract, _tick_skip_counter, message);
IConsolePrintF(colour, "%s", message);
NetworkAddChatMessage((TextColour)colour, _settings_client.gui.network_chat_timeout, "%s", message);
}
@ -879,7 +879,7 @@ void NetworkGameLoop()
/* We don't want to log multiple times if paused. */
static Date last_log;
if (last_log != _date) {
DEBUG(desync, 1, "sync: %08x; %02x; %08x; %08x", _date, _date_fract, _random.state[0], _random.state[1]);
DEBUG(desync, 1, "sync: date{%08x; %02x; %02x}; %08x; %08x", _date, _date_fract, _tick_skip_counter, _random.state[0], _random.state[1]);
last_log = _date;
}
}
@ -889,6 +889,7 @@ void NetworkGameLoop()
static FILE *f = FioFOpenFile("commands.log", "rb", SAVE_DIR);
static Date next_date = 0;
static uint32 next_date_fract;
static uint8 next_tick_skip_counter;
static CommandPacket *cp = NULL;
static bool check_sync_state = false;
static uint32 sync_state[2];
@ -901,16 +902,16 @@ void NetworkGameLoop()
if (_date == next_date && _date_fract == next_date_fract) {
if (cp != NULL) {
NetworkSendCommand(cp->tile, cp->p1, cp->p2, cp->cmd & ~CMD_FLAGS_MASK, NULL, cp->text, cp->company);
DEBUG(net, 0, "injecting: %08x; %02x; %02x; %06x; %08x; %08x; %08x; \"%s\" (%s)", _date, _date_fract, (int)_current_company, cp->tile, cp->p1, cp->p2, cp->cmd, cp->text, GetCommandName(cp->cmd));
DEBUG(net, 0, "injecting: date{%08x; %02x; %02x}; %02x; %06x; %08x; %08x; %08x; \"%s\" (%s)", _date, _date_fract, _tick_skip_counter, (int)_current_company, cp->tile, cp->p1, cp->p2, cp->cmd, cp->text, GetCommandName(cp->cmd));
free(cp);
cp = NULL;
}
if (check_sync_state) {
if (sync_state[0] == _random.state[0] && sync_state[1] == _random.state[1]) {
DEBUG(net, 0, "sync check: %08x; %02x; match", _date, _date_fract);
DEBUG(net, 0, "sync check: date{%08x; %02x; %02x}; match", _date, _date_fract, _tick_skip_counter);
} else {
DEBUG(net, 0, "sync check: %08x; %02x; mismatch expected {%08x, %08x}, got {%08x, %08x}",
_date, _date_fract, sync_state[0], sync_state[1], _random.state[0], _random.state[1]);
DEBUG(net, 0, "sync check: date{%08x; %02x; %02x}; mismatch expected {%08x, %08x}, got {%08x, %08x}",
_date, _date_fract, _tick_skip_counter, sync_state[0], sync_state[1], _random.state[0], _random.state[1]);
NOT_REACHED();
}
check_sync_state = false;
@ -939,17 +940,17 @@ void NetworkGameLoop()
if (*p == ' ') p++;
cp = CallocT<CommandPacket>(1);
int company;
int ret = sscanf(p, "%x; %x; %x; %x; %x; %x; %x; \"%[^\"]\"", &next_date, &next_date_fract, &company, &cp->tile, &cp->p1, &cp->p2, &cp->cmd, cp->text);
/* There are 8 pieces of data to read, however the last is a
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, cp->text);
/* 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. */
assert(ret == 8 || ret == 7);
assert(ret == 9 || ret == 8);
cp->company = (CompanyID)company;
} else if (strncmp(p, "join: ", 6) == 0) {
/* Manually insert a pause when joining; this way the client can join at the exact right time. */
int ret = sscanf(p + 6, "%x; %x", &next_date, &next_date_fract);
assert(ret == 2);
DEBUG(net, 0, "injecting pause for join at %08x:%02x; please join when paused", next_date, next_date_fract);
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);
cp = CallocT<CommandPacket>(1);
cp->company = COMPANY_SPECTATOR;
cp->cmd = CMD_PAUSE;
@ -957,8 +958,8 @@ void NetworkGameLoop()
cp->p2 = 1;
_ddc_fastforward = false;
} else if (strncmp(p, "sync: ", 6) == 0) {
int ret = sscanf(p + 6, "%x; %x; %x; %x", &next_date, &next_date_fract, &sync_state[0], &sync_state[1]);
assert(ret == 4);
int ret = sscanf(p + 6, "date{%x; %x; %x}; %x; %x", &next_date, &next_date_fract, &next_tick_skip_counter, &sync_state[0], &sync_state[1]);
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) {

@ -255,7 +255,7 @@ void ClientNetworkGameSocketHandler::ClientError(NetworkRecvStatus res)
if (_sync_seed_1 != _random.state[0]) {
#endif
NetworkError(STR_NETWORK_ERROR_DESYNC);
DEBUG(desync, 1, "sync_err: %08x; %02x; %02X", _date, _date_fract, _tick_skip_counter);
DEBUG(desync, 1, "sync_err: date{%08x; %02x; %02x}", _date, _date_fract, _tick_skip_counter);
DEBUG(net, 0, "Sync error detected!");
my_client->ClientError(NETWORK_RECV_STATUS_DESYNC);

@ -953,7 +953,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: %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}; %02x; %02x", _date, _date_fract, _tick_skip_counter, (int)ci->client_playas, (int)ci->index);
/* Make sure companies to which people try to join are not autocleaned */
if (Company::IsValidID(playas)) _network_company_states[playas].months_empty = 0;
@ -1611,7 +1611,7 @@ void NetworkUpdateClientInfo(ClientID client_id)
if (ci == NULL) return;
DEBUG(desync, 1, "client: %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}; %02x; %04x", _date, _date_fract, _tick_skip_counter, (int)ci->client_playas, client_id);
FOR_ALL_CLIENT_SOCKETS(cs) {
cs->SendClientInfo(ci);

@ -2943,7 +2943,7 @@ SaveOrLoadResult SaveOrLoad(const char *filename, SaveLoadOperation fop, Detaile
}
if (fop == SLO_SAVE) { // SAVE game
DEBUG(desync, 1, "save: %08x; %02x; %02X; %s", _date, _date_fract, _tick_skip_counter, filename);
DEBUG(desync, 1, "save: date{%08x; %02x; %02x}; %s", _date, _date_fract, _tick_skip_counter, filename);
if (_network_server || !_settings_client.gui.threaded_saves) threaded = false;
return DoSave(new FileWriter(fh), threaded);

Loading…
Cancel
Save