Network: Extend post-desync frame sync history

Record sync state at various points throughout each frame
pull/590/head
Jonathan G Rennison 9 months ago
parent 8e755bf0c2
commit cdf1ff8d5a

@ -638,8 +638,8 @@ char *CrashLog::FillDesyncCrashLog(char *buffer, const char *last, const DesyncE
flag_check(DesyncExtraInfo::DEIF_RAND, "R"),
flag_check(DesyncExtraInfo::DEIF_STATE, "S"));
}
if (_network_server && (info.desync_frame_seed || info.desync_frame_state_checksum)) {
buffer += seprintf(buffer, last, "Desync frame: %08X (seed), %08X (state checksum)\n", info.desync_frame_seed, info.desync_frame_state_checksum);
if (_network_server && !info.desync_frame_info.empty()) {
buffer += seprintf(buffer, last, "%s\n", info.desync_frame_info.c_str());
}
extern uint32 _frame_counter;

@ -28,8 +28,7 @@ struct DesyncExtraInfo {
Flags flags = DEIF_NONE;
const char *client_name = nullptr;
int client_id = -1;
uint32 desync_frame_seed = 0;
uint32 desync_frame_state_checksum = 0;
std::string desync_frame_info;
FILE **log_file = nullptr; ///< save unclosed log file handle here
DesyncDeferredSaveInfo *defer_savegame_write = nullptr;
};

@ -36,6 +36,7 @@
#include "3rdparty/cpp-btree/btree_set.h"
#include "scope_info.h"
#include "core/ring_buffer.hpp"
#include "network/network_sync.h"
#include <array>
#include <list>
#include <set>
@ -786,6 +787,7 @@ void RunTileLoop(bool apply_day_length)
}
_cur_tileloop_tile = tile;
RecordSyncEvent(NSRE_TILE);
}
void RunAuxiliaryTileLoop()
@ -813,6 +815,7 @@ void RunAuxiliaryTileLoop()
}
_aux_tileloop_tile = tile;
RecordSyncEvent(NSRE_AUX_TILE);
}
void InitializeLandscape()
@ -1627,9 +1630,13 @@ void CallLandscapeTick()
PerformanceAccumulator framerate(PFE_GL_LANDSCAPE);
OnTick_Town();
RecordSyncEvent(NSRE_TOWN);
OnTick_Trees();
RecordSyncEvent(NSRE_TREE);
OnTick_Station();
RecordSyncEvent(NSRE_STATION);
OnTick_Industry();
RecordSyncEvent(NSRE_INDUSTRY);
}
OnTick_LinkGraph();

@ -30,6 +30,7 @@ add_files(
network_stun.h
network_survey.cpp
network_survey.h
network_sync.h
network_turn.cpp
network_turn.h
network_type.h

@ -90,9 +90,9 @@ uint32 _last_sync_frame_counter; ///< "
bool _network_first_time; ///< Whether we have finished joining or not.
CompanyMask _network_company_passworded; ///< Bitmask of the password status of all companies.
std::vector<NetworkSyncRecord> _network_client_sync_records;
std::unique_ptr<std::array<NetworkSyncRecord, 1024>> _network_server_sync_records;
uint32 _network_server_sync_records_next;
ring_buffer<NetworkSyncRecord> _network_sync_records;
ring_buffer<uint> _network_sync_record_counts;
bool _record_sync_records = false;
static_assert((int)NETWORK_COMPANY_NAME_LENGTH == MAX_LENGTH_COMPANY_NAME_CHARS * MAX_CHAR_LENGTH);
@ -674,9 +674,10 @@ void NetworkClose(bool close_admins)
InitializeNetworkPools(close_admins);
_network_client_sync_records.clear();
_network_client_sync_records.shrink_to_fit();
_network_server_sync_records.reset();
_network_sync_records.clear();
_network_sync_records.shrink_to_fit();
_network_sync_record_counts.clear();
_network_sync_record_counts.shrink_to_fit();
}
/* Initializes the network (cleans sockets and stuff) */
@ -968,9 +969,9 @@ bool NetworkServerStart()
_last_sync_frame = 0;
_network_own_client_id = CLIENT_ID_SERVER;
_network_server_sync_records.reset(new std::array<NetworkSyncRecord, 1024>());
_network_server_sync_records->fill({ 0, 0, 0 });
_network_server_sync_records_next = 0;
_network_sync_records.clear();
_network_sync_record_counts.clear();
_record_sync_records = false;
_network_clients_connected = 0;
_network_company_passworded = 0;
@ -1111,6 +1112,42 @@ void NetworkBackgroundLoop()
NetworkBackgroundUDPLoop();
}
void RecordSyncEventData(NetworkSyncRecordEvents event)
{
_network_sync_records.push_back({ event, _random.state[0], _state_checksum.state });
}
const char *GetSyncRecordEventName(NetworkSyncRecordEvents event)
{
static const char *names[] = {
"BEGIN",
"CMD",
"AUX_TILE",
"TILE",
"TOWN",
"TREE",
"STATION",
"INDUSTRY",
"PRE_COMPANY_STATE",
"VEH_PERIODIC",
"VEH_LOAD_UNLOAD",
"VEH_EFFECT",
"VEH_TRAIN",
"VEH_ROAD",
"VEH_AIR",
"VEH_SHIP",
"VEH_OTHER",
"VEH_SELL",
"VEH_TBTR",
"VEH_AUTOREPLACE",
"VEH_REPAIR",
"FRAME_DONE"
};
static_assert(lengthof(names) == NSRE_LAST);
if (event < NSRE_LAST) return names[event];
return "???";
}
/* The main loop called from ttd.c
* Here we also have to do StateGameLoop if needed! */
void NetworkGameLoop()
@ -1254,6 +1291,10 @@ void NetworkGameLoop()
send_frame = true;
}
const size_t total_sync_records = _network_sync_records.size();
_network_sync_records.push_back({ _frame_counter, _random.state[0], _state_checksum.state });
_record_sync_records = true;
NetworkExecuteLocalCommandQueue();
if (_pause_countdown > 0 && --_pause_countdown == 0) DoCommandP(0, PM_PAUSED_NORMAL, 1, CMD_PAUSE);
@ -1263,8 +1304,14 @@ void NetworkGameLoop()
_sync_seed_1 = _random.state[0];
_sync_state_checksum = _state_checksum.state;
(*_network_server_sync_records)[_network_server_sync_records_next] = { _frame_counter, _random.state[0], _state_checksum.state };
_network_server_sync_records_next = (_network_server_sync_records_next + 1) % _network_server_sync_records->size();
_network_sync_records.push_back({ NSRE_FRAME_DONE, _random.state[0], _state_checksum.state });
_network_sync_record_counts.push_back((uint)(_network_sync_records.size() - total_sync_records));
_record_sync_records = false;
if (_network_sync_record_counts.size() >= 256) {
/* Remove records from start of queue */
_network_sync_records.erase(_network_sync_records.begin(), _network_sync_records.begin() + _network_sync_record_counts[0]);
_network_sync_record_counts.pop_front();
}
NetworkServer_Tick(send_frame);
} else {

@ -309,10 +309,18 @@ void ClientNetworkGameSocketHandler::ClientError(NetworkRecvStatus res)
{
_frame_counter++;
const size_t total_sync_records = _network_sync_records.size();
_network_sync_records.push_back({ _frame_counter, _random.state[0], _state_checksum.state });
_record_sync_records = true;
NetworkExecuteLocalCommandQueue();
StateGameLoop();
_network_sync_records.push_back({ NSRE_FRAME_DONE, _random.state[0], _state_checksum.state });
_network_sync_record_counts.push_back((uint)(_network_sync_records.size() - total_sync_records));
_record_sync_records = false;
/* Check if we are in sync! */
if (_sync_frame != 0) {
if (_sync_frame == _frame_counter) {
@ -341,7 +349,8 @@ void ClientNetworkGameSocketHandler::ClientError(NetworkRecvStatus res)
_last_sync_date_fract = _date_fract;
_last_sync_tick_skip_counter = _tick_skip_counter;
_last_sync_frame_counter = _sync_frame;
_network_client_sync_records.clear();
_network_sync_records.clear();
_network_sync_record_counts.clear();
/* If this is the first time we have a sync-frame, we
* need to let the server know that we are ready and at the same
@ -358,8 +367,10 @@ void ClientNetworkGameSocketHandler::ClientError(NetworkRecvStatus res)
}
}
if (_network_client_sync_records.size() <= 256) {
_network_client_sync_records.push_back({ _frame_counter, _random.state[0], _state_checksum.state });
if (_network_sync_record_counts.size() >= 128) {
/* Remove records from start of queue */
_network_sync_records.erase(_network_sync_records.begin(), _network_sync_records.begin() + _network_sync_record_counts[0]);
_network_sync_record_counts.pop_front();
}
return true;
@ -632,14 +643,30 @@ NetworkRecvStatus ClientNetworkGameSocketHandler::SendDesyncMessage(const char *
/** Send an error-packet over the network */
NetworkRecvStatus ClientNetworkGameSocketHandler::SendDesyncSyncData()
{
if (_network_client_sync_records.empty()) return NETWORK_RECV_STATUS_OKAY;
if (_network_sync_record_counts.empty()) return NETWORK_RECV_STATUS_OKAY;
uint total = 0;
for (uint32 count : _network_sync_record_counts) {
total += count;
}
if ((size_t)total != _network_sync_records.size()) {
DEBUG(net, 0, "Network sync record error");
return NETWORK_RECV_STATUS_OKAY;
}
Packet *p = new Packet(PACKET_CLIENT_DESYNC_SYNC_DATA, SHRT_MAX);
p->Send_uint32(_network_client_sync_records[0].frame);
p->Send_uint32((uint)_network_client_sync_records.size());
for (uint i = 0; i < (uint)_network_client_sync_records.size(); i++) {
p->Send_uint32(_network_client_sync_records[i].seed_1);
p->Send_uint64(_network_client_sync_records[i].state_checksum);
p->Send_uint32((uint32)_network_sync_record_counts.size());
uint32 offset = 0;
for (uint32 count : _network_sync_record_counts) {
p->Send_uint32(count);
for (uint i = 0; i < count; i++) {
const NetworkSyncRecord &record = _network_sync_records[offset + i];
p->Send_uint32(record.frame);
p->Send_uint32(record.seed_1);
p->Send_uint64(record.state_checksum);
}
offset += count;
}
my_client->SendPacket(p);
return NETWORK_RECV_STATUS_OKAY;

@ -214,6 +214,7 @@ void NetworkExecuteLocalCommandQueue()
CommandQueue &queue = (_network_server ? _local_execution_queue : ClientNetworkGameSocketHandler::my_client->incoming_queue);
bool record_sync_event = false;
CommandPacket *cp;
while ((cp = queue.Peek()) != nullptr) {
/* The queue is always in order, which means
@ -233,11 +234,15 @@ void NetworkExecuteLocalCommandQueue()
DoCommandP(cp, cp->my_cmd);
queue.Pop();
record_sync_event = true;
}
/* Local company may have changed, so we should not restore the old value */
_current_company = _local_company;
_cmd_client_id = INVALID_CLIENT_ID;
if (record_sync_event) RecordSyncEvent(NSRE_CMD);
}
/**

@ -11,6 +11,7 @@
#define NETWORK_INTERNAL_H
#include "network_func.h"
#include "network_sync.h"
#include "core/tcp_coordinator.h"
#include "core/tcp_game.h"
@ -18,8 +19,6 @@
#include "../date_type.h"
#include <vector>
#include <array>
#include <memory>
static const uint32 FIND_SERVER_EXTENDED_TOKEN = 0x2A49582A;
@ -96,16 +95,6 @@ extern uint8 _network_reconnect;
extern CompanyMask _network_company_passworded;
/* Sync debugging */
struct NetworkSyncRecord {
uint32 frame;
uint32 seed_1;
uint64 state_checksum;
};
extern std::vector<NetworkSyncRecord> _network_client_sync_records;
extern std::unique_ptr<std::array<NetworkSyncRecord, 1024>> _network_server_sync_records;
extern uint32 _network_server_sync_records_next;
void NetworkQueryServer(const std::string &connection_string);
void GetBindAddresses(NetworkAddressList *addresses, uint16 port);

@ -1291,8 +1291,7 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_ERROR(Packet *p
DesyncExtraInfo info;
info.client_name = client_name;
info.client_id = this->client_id;
info.desync_frame_seed = this->desync_frame_seed;
info.desync_frame_state_checksum = this->desync_frame_state_checksum;
info.desync_frame_info = std::move(this->desync_frame_info);
CrashLog::DesyncCrashLog(&(this->desync_log), &server_desync_log, info);
this->SendDesyncLog(server_desync_log);
@ -1336,32 +1335,58 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_DESYNC_MSG(Pack
NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_DESYNC_SYNC_DATA(Packet *p)
{
uint32 frame = p->Recv_uint32();
uint32 count = p->Recv_uint32();
DEBUG(net, 2, "Received desync sync data: %u frames from %08X", count, frame);
uint32 frame_count = p->Recv_uint32();
DEBUG(net, 2, "Received desync sync data: %u frames", frame_count);
if (frame_count == 0 || _network_sync_record_counts.empty()) return NETWORK_RECV_STATUS_OKAY;
size_t record_count_offset = 0;
size_t record_offset = 0;
for (uint i = 0; i < frame_count; i++) {
uint32 item_count = p->Recv_uint32();
if (item_count == 0) continue;
uint32 local_item_count = 0;
uint32 frame = 0;
NetworkSyncRecordEvents event = NSRE_BEGIN;
for (uint j = 0; j < item_count; j++) {
if (j == 0) {
frame = p->Recv_uint32();
while (_network_sync_records[record_offset].frame != frame) {
if (record_count_offset == _network_sync_record_counts.size()) {
return NETWORK_RECV_STATUS_OKAY;
}
record_offset += _network_sync_record_counts[record_count_offset];
record_count_offset++;
}
local_item_count = _network_sync_record_counts[record_count_offset];
} else {
event = (NetworkSyncRecordEvents)p->Recv_uint32();
}
uint32 seed_1 = p->Recv_uint32();
uint64 state_checksum = p->Recv_uint64();
if (j == local_item_count) {
this->desync_frame_info = stdstr_fmt("Desync subframe count mismatch: extra client record: %08X, %s", frame, GetSyncRecordEventName(event));
return NETWORK_RECV_STATUS_OKAY;
}
uint server_idx = UINT32_MAX;
for (uint i = 0; i < _network_server_sync_records->size(); i++) {
if ((*_network_server_sync_records)[i].frame == frame) {
server_idx = i;
break;
const NetworkSyncRecord &record = _network_sync_records[record_offset + j];
if (j != 0 && record.frame != event) {
this->desync_frame_info = stdstr_fmt("Desync subframe event mismatch: %08X, client: %s != server: %s",
frame, GetSyncRecordEventName(event), GetSyncRecordEventName((NetworkSyncRecordEvents)record.frame));
return NETWORK_RECV_STATUS_OKAY;
}
if (seed_1 != record.seed_1 || state_checksum != record.state_checksum) {
this->desync_frame_info = stdstr_fmt("Desync subframe mismatch: %08X, %s%s%s",
frame, GetSyncRecordEventName(event), (seed_1 != record.seed_1) ? ", seed" : "", (state_checksum != record.state_checksum) ? ", state checksum" : "");
return NETWORK_RECV_STATUS_OKAY;
}
}
if (local_item_count > item_count) {
const NetworkSyncRecord &record = _network_sync_records[record_offset + item_count];
this->desync_frame_info = stdstr_fmt("Desync subframe count mismatch: extra server record: %08X, %s", frame, GetSyncRecordEventName((NetworkSyncRecordEvents)record.frame));
return NETWORK_RECV_STATUS_OKAY;
}
}
if (server_idx == UINT32_MAX) return NETWORK_RECV_STATUS_OKAY;
for (uint i = 0; i < count; i++) {
uint32 seed_1 = p->Recv_uint32();
uint64 state_checksum = p->Recv_uint64();
const NetworkSyncRecord &record = (*_network_server_sync_records)[server_idx];
if (record.frame != frame) break;
if (record.seed_1 != seed_1 && this->desync_frame_seed == 0) this->desync_frame_seed = frame;
if (record.state_checksum != state_checksum && this->desync_frame_state_checksum == 0) this->desync_frame_state_checksum = frame;
frame++;
server_idx = (server_idx + 1) % _network_server_sync_records->size();
}
return NETWORK_RECV_STATUS_OKAY;

@ -89,9 +89,7 @@ public:
NetworkAddress client_address; ///< IP-address of the client (so they can be banned)
std::string desync_log;
uint desync_frame_seed = 0;
uint desync_frame_state_checksum = 0;
std::string desync_frame_info;
uint rcon_auth_failures = 0;
uint settings_auth_failures = 0;

@ -0,0 +1,61 @@
/*
* This file is part of OpenTTD.
* OpenTTD is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free Software Foundation, version 2.
* OpenTTD is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
* See the GNU General Public License for more details. You should have received a copy of the GNU General Public License along with OpenTTD. If not, see <http://www.gnu.org/licenses/>.
*/
/** @file network_sync.h Variables and function used for network sync tracking. */
#ifndef NETWORK_SYNC_H
#define NETWORK_SYNC_H
#include "../core/ring_buffer.hpp"
/* Sync debugging */
struct NetworkSyncRecord {
uint32 frame;
uint32 seed_1;
uint64 state_checksum;
};
extern ring_buffer<NetworkSyncRecord> _network_sync_records;
extern ring_buffer<uint> _network_sync_record_counts;
extern bool _record_sync_records;
enum NetworkSyncRecordEvents : uint32 {
NSRE_BEGIN,
NSRE_CMD,
NSRE_AUX_TILE,
NSRE_TILE,
NSRE_TOWN,
NSRE_TREE,
NSRE_STATION,
NSRE_INDUSTRY,
NSRE_PRE_COMPANY_STATE,
NSRE_VEH_PERIODIC,
NSRE_VEH_LOAD_UNLOAD,
NSRE_VEH_EFFECT,
NSRE_VEH_TRAIN,
NSRE_VEH_ROAD,
NSRE_VEH_AIR,
NSRE_VEH_SHIP,
NSRE_VEH_OTHER,
NSRE_VEH_SELL,
NSRE_VEH_TBTR,
NSRE_VEH_AUTOREPLACE,
NSRE_VEH_REPAIR,
NSRE_FRAME_DONE,
NSRE_LAST,
};
void RecordSyncEventData(NetworkSyncRecordEvents event);
const char *GetSyncRecordEventName(NetworkSyncRecordEvents event);
inline void RecordSyncEvent(NetworkSyncRecordEvents event)
{
if (_record_sync_records) {
RecordSyncEventData(event);
}
}
#endif /* NETWORK_SYNC_H */

@ -91,6 +91,7 @@
#include "network/network_survey.h"
#include "timer/timer.h"
#include "timer/timer_game_tick.h"
#include "network/network_sync.h"
#include "linkgraph/linkgraphschedule.h"
#include "tracerestrict.h"
@ -2133,6 +2134,7 @@ void StateGameLoop()
NewsLoop();
if (_networking) {
RecordSyncEvent(NSRE_PRE_COMPANY_STATE);
for (Company *c : Company::Iterate()) {
DEBUG_UPDATESTATECHECKSUM("Company: %u, Money: " OTTD_PRINTF64, c->index, (int64)c->money);
UpdateStateChecksum(c->money);

@ -60,6 +60,7 @@
#include "string_func.h"
#include "scope_info.h"
#include "debug_settings.h"
#include "network/network_sync.h"
#include "3rdparty/cpp-btree/btree_set.h"
#include "3rdparty/cpp-btree/btree_map.h"
@ -1498,6 +1499,8 @@ void CallVehicleTicks()
}
}
RecordSyncEvent(NSRE_VEH_PERIODIC);
{
PerformanceMeasurer framerate(PFE_GL_ECONOMY);
Station *si_st = nullptr;
@ -1508,6 +1511,8 @@ void CallVehicleTicks()
}
}
RecordSyncEvent(NSRE_VEH_LOAD_UNLOAD);
if (!_tick_caches_valid || HasChickenBit(DCBF_VEH_TICK_CACHE)) RebuildVehicleTickCaches();
Vehicle *v = nullptr;
@ -1523,9 +1528,10 @@ void CallVehicleTicks()
u->EffectVehicle::Tick();
}
}
if (!_tick_effect_veh_cache.empty()) RecordSyncEvent(NSRE_VEH_EFFECT);
{
PerformanceMeasurer framerate(PFE_GL_TRAINS);
for (Train *t : _tick_train_too_heavy_cache) {
for (Train *t : _tick_train_too_heavy_cache) {
if (HasBit(t->flags, VRF_TOO_HEAVY)) {
if (t->owner == _local_company) {
SetDParam(0, t->index);
@ -1546,6 +1552,7 @@ void CallVehicleTicks()
}
}
}
RecordSyncEvent(NSRE_VEH_TRAIN);
{
PerformanceMeasurer framerate(PFE_GL_ROADVEHS);
for (RoadVehicle *front : _tick_road_veh_front_cache) {
@ -1558,6 +1565,7 @@ void CallVehicleTicks()
if (!(front->vehstatus & VS_STOPPED)) VehicleTickMotion(front, front);
}
}
if (!_tick_road_veh_front_cache.empty()) RecordSyncEvent(NSRE_VEH_ROAD);
{
PerformanceMeasurer framerate(PFE_GL_AIRCRAFT);
for (Aircraft *front : _tick_aircraft_front_cache) {
@ -1569,6 +1577,7 @@ void CallVehicleTicks()
if (!(front->vehstatus & VS_STOPPED)) VehicleTickMotion(front, front);
}
}
if (!_tick_aircraft_front_cache.empty()) RecordSyncEvent(NSRE_VEH_AIR);
{
PerformanceMeasurer framerate(PFE_GL_SHIPS);
for (Ship *s : _tick_ship_cache) {
@ -1580,6 +1589,7 @@ void CallVehicleTicks()
if (!(s->vehstatus & VS_STOPPED)) VehicleTickMotion(s, s);
}
}
if (!_tick_ship_cache.empty()) RecordSyncEvent(NSRE_VEH_SHIP);
{
for (Vehicle *u : _tick_other_veh_cache) {
if (!u) continue;
@ -1588,6 +1598,7 @@ void CallVehicleTicks()
}
}
v = nullptr;
if (!_tick_other_veh_cache.empty()) RecordSyncEvent(NSRE_VEH_OTHER);
/* Handle vehicles marked for immediate sale */
Backup<CompanyID> sell_cur_company(_current_company, FILE_LINE);
@ -1616,6 +1627,7 @@ void CallVehicleTicks()
_vehicles_to_autoreplace.erase(index);
}
sell_cur_company.Restore();
if (!_vehicles_to_sell.empty()) RecordSyncEvent(NSRE_VEH_SELL);
/* do Template Replacement */
Backup<CompanyID> tmpl_cur_company(_current_company, FILE_LINE);
@ -1664,6 +1676,7 @@ void CallVehicleTicks()
}
}
tmpl_cur_company.Restore();
if (!_vehicles_to_templatereplace.empty()) RecordSyncEvent(NSRE_VEH_TBTR);
/* do Auto Replacement */
Backup<CompanyID> cur_company(_current_company, FILE_LINE);
@ -1701,6 +1714,7 @@ void CallVehicleTicks()
ShowAutoReplaceAdviceMessage(res, v);
}
cur_company.Restore();
if (!_vehicles_to_autoreplace.empty()) RecordSyncEvent(NSRE_VEH_AUTOREPLACE);
Backup<CompanyID> repair_cur_company(_current_company, FILE_LINE);
for (VehicleID index : _vehicles_to_pay_repair) {
@ -1743,6 +1757,7 @@ void CallVehicleTicks()
v->breakdowns_since_last_service = 0;
}
repair_cur_company.Restore();
if (!_vehicles_to_pay_repair.empty()) RecordSyncEvent(NSRE_VEH_REPAIR);
_vehicles_to_pay_repair.clear();
}

Loading…
Cancel
Save