/**
* @brief serverside network receiver
*
* Plugin for the CGameServer network code in GameServer.cpp.
* @return the number of bytes read from the network stream
*/
bool CSyncDebugger::ServerReceived(const unsigned char* inbuf)
{
bool syncDebugPacket = false;
switch (inbuf[0]) {
case NETMSG_SD_CHKRESPONSE:
if (*(short*)&inbuf[1] != HISTORY_SIZE * sizeof(unsigned) + 12) {
logger.AddLine("Server: received checksum response of %d instead of %d bytes", *(short*)&inbuf[1], HISTORY_SIZE * 4 + 12);
} else {
int player = inbuf[3];
if(player >= playerHandler->ActivePlayers() || player < 0) {
logger.AddLine("Server: got invalid playernum %d in checksum response", player);
} else {
logger.AddLine("Server: got checksum response from %d", player);
const unsigned* begin = (unsigned*)&inbuf[12];
const unsigned* end = begin + HISTORY_SIZE;
players[player].checksumResponses.resize(HISTORY_SIZE);
std::copy(begin, end, players[player].checksumResponses.begin());
players[player].remoteFlop = *(uint64_t*)&inbuf[4];
assert(!players[player].checksumResponses.empty());
int i = 0;
while (i < playerHandler->ActivePlayers() && !players[i].checksumResponses.empty()) ++i;
if (i == playerHandler->ActivePlayers()) {
ServerQueueBlockRequests();
logger.AddLine("Server: checksum responses received; %d block requests queued", pendingBlocksToRequest.size());
}
}
}
syncDebugPacket = true;
break;
case NETMSG_SD_BLKRESPONSE:
if (*(short*)&inbuf[1] != BLOCK_SIZE * sizeof(unsigned) + 4) {
logger.AddLine("Server: received block response of %d instead of %d bytes", *(short*)&inbuf[1], BLOCK_SIZE * 4 + 4);
} else {
int player = inbuf[3];
if(player >= playerHandler->ActivePlayers() || player < 0) {
logger.AddLine("Server: got invalid playernum %d in block response", player);
} else {
const unsigned* begin = (unsigned*)&inbuf[4];
const unsigned* end = begin + BLOCK_SIZE;
unsigned size = players[player].remoteHistory.size();
players[player].remoteHistory.resize(size + BLOCK_SIZE);
std::copy(begin, end, players[player].remoteHistory.begin() + size);
int i = 0;
size += BLOCK_SIZE;
while (i < playerHandler->ActivePlayers() && size == players[i].remoteHistory.size()) ++i;
if (i == playerHandler->ActivePlayers()) {
logger.AddLine("Server: block responses received");
ServerReceivedBlockResponses();
}
}
}
syncDebugPacket = true;
break;
default:
logger.AddLine("Server: unknown packet");
break;
}
logger.FlushBuffer();
return syncDebugPacket;
}
void CSyncDebugger::Initialize(bool useBacktrace, unsigned numPlayers)
{
delete[] history;
history = NULL;
delete[] historybt;
historybt = NULL;
#ifdef HAVE_BACKTRACE
if (useBacktrace) {
historybt = new HistItemWithBacktrace[HISTORY_SIZE * BLOCK_SIZE];
memset(historybt, 0, HISTORY_SIZE * BLOCK_SIZE * sizeof(HistItemWithBacktrace));
} else
#endif
{
history = new HistItem[HISTORY_SIZE * BLOCK_SIZE];
memset(history, 0, HISTORY_SIZE * BLOCK_SIZE * sizeof(HistItem));
}
//cleanup
historyIndex = 0;
disable_history = false;
may_enable_history = false;
flop = 0;
players.clear();
players.resize(numPlayers);
pendingBlocksToRequest.clear();
waitingForBlockResponse = false;
// init logger
logger.SetFilename(useBacktrace ? LOGFILE_SERVER : LOGFILE_CLIENT);
logger.AddLine("SyncDebugger initialized");
logger.FlushBuffer();
}
/**
* @brief output a backtrace to the log
*
* Writes the backtrace attached to history item # index to the log.
* The backtrace is prefixed with prefix.
*/
void CSyncDebugger::Backtrace(int index, const char* prefix) const
{
if (historybt) {
for (unsigned i = 0; i < historybt[index].bt_size; ++i) {
// the "{%p}" part is resolved to "functionname [filename:lineno]"
// by the CLogger class.
#ifndef _WIN32
logger.AddLine("%s#%u {%p}", prefix, i, historybt[index].bt[i]);
#else
if (sizeof(void*) == 8)
logger.AddLine("%s#%u {%llx}", prefix, i, (uint64_t)historybt[index].bt[i]);
else
logger.AddLine("%s#%u {%x}", prefix, i, (uint32_t)historybt[index].bt[i]);
#endif
}
}
}
/**
* @brief clientside network receiver
*
* Plugin for the CGame network code in Game.cpp.
* @return the number of bytes read from the network stream
*/
int CSyncDebugger::ClientReceived(const unsigned char* inbuf)
{
int length = 0;
switch (inbuf[0]) {
case NETMSG_SD_CHKREQUEST:
if (gs->frameNum != *(int*)&inbuf[1]) {
logger.AddLine("Client: received checksum request for frame %d instead of %d", *(int*)&inbuf[1], gs->frameNum);
} else {
disable_history = true; // no more additions to the history until we're done
may_enable_history = false;
ClientSendChecksumResponse();
logger.AddLine("Client: checksum response sent");
}
length = 5;
break;
case NETMSG_SD_BLKREQUEST:
if (*(unsigned short*)&inbuf[1] >= HISTORY_SIZE) {
logger.AddLine("Client: invalid block number %d in block request", *(unsigned short*)&inbuf[1]);
} else {
ClientSendBlockResponse(*(unsigned short*)&inbuf[1]);
logger.AddLine("Client: block response sent for block %d", *(unsigned short*)&inbuf[1]);
// simple progress indication
logOutput.Print("[SD] Client: %d / %d", *(unsigned short*)&inbuf[3], *(unsigned short*)&inbuf[5]);
}
length = 7;
break;
case NETMSG_SD_RESET:
logger.CloseSession();
logOutput.Print("[SD] Client: Done!");
// disable_history = false;
may_enable_history = true;
if (gu->autoQuit) {
logOutput.Print("[SD] Client: Automatical quit enforced from commandline");
globalQuit = true;
}
length = 1;
break;
default:
logOutput.Print("[SD] Client: invalid msg");
length = 0;
break;
}
return length;
}
void CSyncDebugger::ServerQueueBlockRequests()
{
logger.AddLine("Server: queuing block requests");
boost::uint64_t correctFlop = 0;
for (int j = 0; j < playerHandler->ActivePlayers(); ++j) {
if (correctFlop) {
if (players[j].remoteFlop != correctFlop)
logger.AddLine(
#ifdef _WIN32
"Server: bad flop# %I64u instead of %I64u for player %d",
#else
"Server: bad flop# %llu instead of %llu for player %d",
#endif
players[j].remoteFlop, correctFlop, j);
} else {
correctFlop = players[j].remoteFlop;
}
}
unsigned i = ((unsigned)(correctFlop % (HISTORY_SIZE * BLOCK_SIZE)) / BLOCK_SIZE) + 1;
for (unsigned c = 0; c < HISTORY_SIZE; ++i, ++c) {
unsigned correctChecksum = 0;
if (i == HISTORY_SIZE) i = 0;
for (int j = 0; j < playerHandler->ActivePlayers(); ++j) {
if (correctChecksum && players[j].checksumResponses[i] != correctChecksum) {
pendingBlocksToRequest.push_back(i);
break;
}
correctChecksum = players[j].checksumResponses[i];
}
}
if (!pendingBlocksToRequest.empty()) {
logger.AddLine("Server: blocks: %u equal, %u not equal", HISTORY_SIZE - pendingBlocksToRequest.size(), pendingBlocksToRequest.size());
requestedBlocks = pendingBlocksToRequest;
// we know the first FPU bug occured in block # ii, so we send out a block request for it.
// serverNet->SendData<unsigned> (NETMSG_SD_BLKREQUEST, ii);
} else {
logger.AddLine("Server: huh, all blocks equal?!?");
clientNet->Send(CBaseNetProtocol::Get().SendSdReset());
}
//cleanup
for (PlayerVec::iterator it = players.begin(); it != players.end(); ++it)
it->checksumResponses.clear();
logger.FlushBuffer();
}
/**
* @brief serverside network receiver
*
* Plugin for the CGameServer network code in GameServer.cpp.
* @return the number of bytes read from the network stream
*/
int CSyncDebugger::ServerReceived(const unsigned char* inbuf)
{
int length = 0;
switch (inbuf[0]) {
case NETMSG_SD_CHKRESPONSE:
if (*(short*)&inbuf[1] != HISTORY_SIZE * sizeof(unsigned) + 12) {
logger.AddLine("Server: received checksum response of %d instead of %d bytes", *(short*)&inbuf[1], HISTORY_SIZE * 4 + 12);
} else {
int player = inbuf[3];
if(player >= gs->activeTeams || player < 0) {
logger.AddLine("Server: got invalid playernum %d in checksum response", player);
} else {
const unsigned* begin = (unsigned*)&inbuf[12];
const unsigned* end = begin + HISTORY_SIZE;
checksumResponses[player].resize(HISTORY_SIZE);
std::copy(begin, end, checksumResponses[player].begin());
remoteFlop[player] = *(Uint64*)&inbuf[4];
int i = 0;
while (i < gs->activeTeams && !checksumResponses[i].empty()) ++i;
if (i == gs->activeTeams) {
ServerQueueBlockRequests();
logger.AddLine("Server: checksum responses received; %d block requests queued", pendingBlocksToRequest.size());
}
}
}
length = *(short*)&inbuf[1];
break;
case NETMSG_SD_BLKRESPONSE:
if (*(short*)&inbuf[1] != BLOCK_SIZE * sizeof(unsigned) + 4) {
logger.AddLine("Server: received block response of %d instead of %d bytes", *(short*)&inbuf[1], BLOCK_SIZE * 4 + 4);
} else {
int player = inbuf[3];
if(player >= gs->activeTeams || player < 0) {
logger.AddLine("Server: got invalid playernum %d in block response", player);
} else {
const unsigned* begin = (unsigned*)&inbuf[4];
const unsigned* end = begin + BLOCK_SIZE;
unsigned size = remoteHistory[player].size();
remoteHistory[player].resize(size + BLOCK_SIZE);
std::copy(begin, end, remoteHistory[player].begin() + size);
int i = 0;
size += BLOCK_SIZE;
while (i < gs->activeTeams && size == remoteHistory[i].size()) ++i;
if (i == gs->activeTeams) {
logger.AddLine("Server: block responses received");
ServerReceivedBlockResponses();
}
}
}
length = *(short*)&inbuf[1];
break;
default:
logger.AddLine("Server: invalid msg");
length = 0;
break;
}
return length;
}
/**
* @brief output a backtrace to the log
*
* Writes the backtrace attached to history item # index to the log.
* The backtrace is prefixed with prefix.
*/
void CSyncDebugger::Backtrace(int index, const char* prefix) const
{
if (historybt) {
for (unsigned i = 0; i < historybt[index].bt_size; ++i) {
// the "{%p}" part is resolved to "functionname [filename:lineno]"
// by the CLogger class.
logger.AddLine("%s#%u {%p}", prefix, i, historybt[index].bt[i]);
}
}
}
/**
* @brief clientside network receiver
*
* Plugin for the CGame network code in Game.cpp.
* @return the number of bytes read from the network stream
*/
bool CSyncDebugger::ClientReceived(const unsigned char* inbuf)
{
bool syncDebugPacket = false;
switch (inbuf[0]) {
case NETMSG_SD_CHKREQUEST:
if (gs->frameNum != *(int*)&inbuf[1]) {
logger.AddLine("Client: received checksum request for frame %d instead of %d", *(int*)&inbuf[1], gs->frameNum);
} else {
disable_history = true; // no more additions to the history until we're done
may_enable_history = false;
ClientSendChecksumResponse();
logger.AddLine("Client: checksum response sent");
}
syncDebugPacket = true;
break;
case NETMSG_SD_BLKREQUEST:
if (*(unsigned short*)&inbuf[1] >= HISTORY_SIZE) {
logger.AddLine("Client: invalid block number %d in block request", *(unsigned short*)&inbuf[1]);
} else {
ClientSendBlockResponse(*(unsigned short*)&inbuf[1]);
logger.AddLine("Client: block response sent for block %d", *(unsigned short*)&inbuf[1]);
// simple progress indication
logOutput.Print("[SD] Client: %d / %d", *(unsigned short*)&inbuf[3], *(unsigned short*)&inbuf[5]);
}
syncDebugPacket = true;
break;
case NETMSG_SD_RESET:
logger.CloseSession();
logOutput.Print("[SD] Client: Done!");
// disable_history = false;
may_enable_history = true;
syncDebugPacket = true;
break;
}
logger.FlushBuffer();
return syncDebugPacket;
}
/**
* @brief third step after desync
*
* Called by server after all checksum responses have been received.
* Compares the checksumResponses and figures out which blocks are out of sync
* (have different checksum). For these blocks requests are queued which will
* be send next frames (one request at a time, see
* CSyncDebugger::ServerHandlePendingBlockRequests()).
*/
void CSyncDebugger::ServerQueueBlockRequests()
{
Uint64 correctFlop = 0;
for (int j = 0; j < gs->activeTeams; ++j) {
if (correctFlop) {
if (remoteFlop[j] != correctFlop)
logger.AddLine("Server: bad flop# %llu instead of %llu for player %d", remoteFlop[j], correctFlop, j);
} else {
correctFlop = remoteFlop[j];
}
}
unsigned i = ((unsigned)(correctFlop % (HISTORY_SIZE * BLOCK_SIZE)) / BLOCK_SIZE) + 1, c = 0;
for (; c < HISTORY_SIZE; ++i, ++c) {
unsigned correctChecksum = 0;
if (i == HISTORY_SIZE) i = 0;
for (int j = 0; j < gs->activeTeams; ++j) {
if (correctChecksum && checksumResponses[j][i] != correctChecksum) {
pendingBlocksToRequest.push_back(i);
break;
}
correctChecksum = checksumResponses[j][i];
}
}
if (!pendingBlocksToRequest.empty()) {
logger.AddLine("Server: blocks: %u equal, %u not equal", HISTORY_SIZE - pendingBlocksToRequest.size(), pendingBlocksToRequest.size());
requestedBlocks = pendingBlocksToRequest;
// we know the first FPU bug occured in block # ii, so we send out a block request for it.
// serverNet->SendData<unsigned> (NETMSG_SD_BLKREQUEST, ii);
} else {
logger.AddLine("Server: huh, all blocks equal?!?");
serverNet->SendData(NETMSG_SD_RESET);
}
//cleanup
for (int j = 0; j < MAX_PLAYERS; ++j)
checksumResponses[j].clear();
}
/**
* @brief initialize
*
* Initialize the sync debugger. Pass true for a server (this requires approx.
* 144 megabytes on 32 bit systems and 240 megabytes on 64 bit systems) and
* false for a client (requires only 16 megabytes extra).
* FIXME update this comment to reflect new values
*/
void CSyncDebugger::Initialize(bool useBacktrace, unsigned numPlayers)
{
delete[] history;
history = 0;
delete[] historybt;
historybt = 0;
#ifdef HAVE_BACKTRACE
if (useBacktrace) {
historybt = new HistItemWithBacktrace[HISTORY_SIZE * BLOCK_SIZE];
memset(historybt, 0, HISTORY_SIZE * BLOCK_SIZE * sizeof(HistItemWithBacktrace));
} else
#endif
{
history = new HistItem[HISTORY_SIZE * BLOCK_SIZE];
memset(history, 0, HISTORY_SIZE * BLOCK_SIZE * sizeof(HistItem));
}
//cleanup
historyIndex = 0;
disable_history = false;
may_enable_history = false;
flop = 0;
for (unsigned j = 0; j < numPlayers; ++j) {
PlayerStruct buf;
buf.checksumResponses.clear();
buf.remoteHistory.clear();
buf.remoteFlop = 0;
players.push_back(buf);
}
pendingBlocksToRequest.clear();
waitingForBlockResponse = false;
// init logger
logger.SetFilename(useBacktrace ? LOGFILE_SERVER : LOGFILE_CLIENT);
logger.AddLine("Syncdebugger initialised");
logger.FlushBuffer();
}
/**
* @brief sixth step after desync
*
* Called by server once all blockResponses are received. It dumps a backtrace
* to the logger for every checksum mismatch in the block which was out of
* sync. The backtraces are passed to the logger in a fairly simple form
* consisting basically only of hexadecimal addresses. The logger class
* resolves those to function, filename & line number.
*/
void CSyncDebugger::ServerDumpStack()
{
// first calculate start iterator...
unsigned posInHistory = (unsigned)(players[0].remoteFlop % (HISTORY_SIZE * BLOCK_SIZE));
logger.AddLine("Server: position in history: %u", posInHistory);
unsigned blockNr = posInHistory / BLOCK_SIZE;
unsigned virtualBlockNr = 0; // block nr in remoteHistory (which skips unchanged blocks)
for (; virtualBlockNr < requestedBlocks.size() && requestedBlocks[virtualBlockNr] != blockNr; ++virtualBlockNr) {}
unsigned virtualPosInHistory = (virtualBlockNr * BLOCK_SIZE) + (posInHistory % BLOCK_SIZE) + 1;
unsigned virtualHistorySize = players[0].remoteHistory.size();
if (virtualBlockNr >= requestedBlocks.size())
virtualPosInHistory = virtualHistorySize;
unsigned ndif = 0; // number of differences
assert(virtualPosInHistory <= virtualHistorySize);
// we make a pool of backtraces (to merge identical ones)
unsigned curBacktrace = 0;
std::map<unsigned, unsigned> checksumToIndex;
std::map<unsigned, unsigned> indexToHistPos;
// then loop from virtualPosInHistory to virtualHistorySize and from 0 to virtualPosInHistory.
for (unsigned i = virtualPosInHistory, c = 0; c < virtualHistorySize; ++i, ++c) {
unsigned correctChecksum = 0;
if (i == virtualHistorySize) i = 0;
bool err = false;
for (int j = 0; j < playerHandler->ActivePlayers(); ++j) {
if (correctChecksum && players[j].remoteHistory[i] != correctChecksum) {
if (historybt) {
virtualBlockNr = i / BLOCK_SIZE;
blockNr = requestedBlocks[virtualBlockNr];
unsigned histPos = blockNr * BLOCK_SIZE + i % BLOCK_SIZE;
unsigned checksum = GetBacktraceChecksum(histPos);
std::map<unsigned, unsigned>::iterator it = checksumToIndex.find(checksum);
if (it == checksumToIndex.end()) {
++curBacktrace;
checksumToIndex[checksum] = curBacktrace;
indexToHistPos[curBacktrace] = histPos;
}
logger.AddLine("Server: chk %08X instead of %08X frame %06u, (value=%08x %15.8e) backtrace %u in \"%s\"", players[j].remoteHistory[i], correctChecksum, historybt[histPos].frameNum, historybt[histPos].data, *(float*)&historybt[histPos].data, checksumToIndex[checksum], historybt[histPos].op);
} else {
logger.AddLine("Server: chk %08X instead of %08X", players[j].remoteHistory[i], correctChecksum);
}
err = true;
} else {
correctChecksum = players[j].remoteHistory[i];
}
}
if (err) {
++ndif;
}
}
if (ndif)
logger.AddLine("Server: chks: %d equal, %d not equal", virtualHistorySize - ndif, ndif);
else
// This is impossible (internal error).
// Server first finds there are differing blocks, then all checksums equal??
// Turns out this can happen if the checksum function is weak.
logger.AddLine("Server: huh, all checksums equal?!? (INTERNAL ERROR)");
//cleanup
for (playerVec::iterator it = players.begin(); it != players.end(); ++it)
it->remoteHistory.clear();
if (historybt) {
// output backtraces we collected earlier this function
for (std::map<unsigned, unsigned>::iterator it = indexToHistPos.begin(); it != indexToHistPos.end(); ++it) {
logger.AddLine("Server: === Backtrace %u ===", it->first);
Backtrace(it->second, "Server: ");
}
}
// and reset
net->Send(CBaseNetProtocol::Get().SendSdReset());
logger.AddLine("Server: Done!");
logger.CloseSession();
logOutput.Print("[SD] Server: Done!");
}
