1 /* This file is part of the Spring engine (GPL v2 or later), see LICENSE.html */
2
3
4 #ifdef SYNCDEBUG
5
6 #include "SyncDebugger.h"
7 #include "Game/GlobalUnsynced.h"
8 #include "Game/Players/PlayerHandler.h"
9 #include "Net/Protocol/BaseNetProtocol.h"
10 #include "Sim/Misc/GlobalSynced.h"
11 #include "System/Log/ILog.h"
12 #include "Net/Protocol/NetProtocol.h"
13
14 #include "HsiehHash.h"
15 #include "Logger.h"
16 #include "SyncTracer.h"
17
18 #include <string.h>
19 #include <map>
20
21 #ifndef WIN32
22 /* for backtrace() function */
23 #include <execinfo.h>
24 #define HAVE_BACKTRACE
25 #elif defined __MINGW32__
26 /* from backtrace.c: */
27 extern "C" int backtrace(void** array, int size);
28 #define HAVE_BACKTRACE
29 #else
30 #undef HAVE_BACKTRACE
31 #endif
32
33
34 #define LOGFILE_SERVER "syncdebug-server.log"
35 #define LOGFILE_CLIENT "syncdebug-client.log"
36
37
38 #define LOG_SECTION_SYNC_DEBUGGER "SD"
39 LOG_REGISTER_SECTION_GLOBAL(LOG_SECTION_SYNC_DEBUGGER)
40
41 // use the specific section for all LOG*() calls in this source file
42 #ifdef LOG_SECTION_CURRENT
43 #undef LOG_SECTION_CURRENT
44 #endif
45 #define LOG_SECTION_CURRENT LOG_SECTION_SYNC_DEBUGGER
46
47
48
49 /**
50 * @brief logging instance
51 */
52 static CLogger logger;
53
54
GetInstance()55 CSyncDebugger* CSyncDebugger::GetInstance() {
56 static CSyncDebugger instance;
57 return &instance;
58 }
59
60
CSyncDebugger()61 CSyncDebugger::CSyncDebugger()
62 : history(NULL)
63 , historybt(NULL)
64 , historyIndex(0)
65 , disable_history(false)
66 , may_enable_history(false)
67 , flop(0)
68 , waitingForBlockResponse(false)
69 {
70 }
71
72
~CSyncDebugger()73 CSyncDebugger::~CSyncDebugger()
74 {
75 delete[] history;
76 delete[] historybt;
77 }
78
79
Initialize(bool useBacktrace,unsigned numPlayers)80 void CSyncDebugger::Initialize(bool useBacktrace, unsigned numPlayers)
81 {
82 delete[] history;
83 history = NULL;
84 delete[] historybt;
85 historybt = NULL;
86
87 #ifdef HAVE_BACKTRACE
88 if (useBacktrace) {
89 historybt = new HistItemWithBacktrace[HISTORY_SIZE * BLOCK_SIZE];
90 memset(historybt, 0, HISTORY_SIZE * BLOCK_SIZE * sizeof(HistItemWithBacktrace));
91 } else
92 #endif
93 {
94 history = new HistItem[HISTORY_SIZE * BLOCK_SIZE];
95 memset(history, 0, HISTORY_SIZE * BLOCK_SIZE * sizeof(HistItem));
96 }
97
98 //cleanup
99 historyIndex = 0;
100 disable_history = false;
101 may_enable_history = false;
102 flop = 0;
103 players.clear();
104 players.resize(numPlayers);
105 pendingBlocksToRequest.clear();
106 waitingForBlockResponse = false;
107
108 // init logger
109 logger.SetFilename(useBacktrace ? LOGFILE_SERVER : LOGFILE_CLIENT);
110 logger.AddLine("SyncDebugger initialized");
111 logger.FlushBuffer();
112 }
113
114
Sync(const void * p,unsigned size,const char * op)115 void CSyncDebugger::Sync(const void* p, unsigned size, const char* op)
116 {
117 if (!history && !historybt) {
118 return;
119 }
120
121 HistItem* h = &history[historyIndex];
122
123 #ifdef HAVE_BACKTRACE
124 if (historybt) {
125 // HACK to skip the uppermost 2 or 3 (32 resp. 64 bit) frames without memcpy'ing the whole backtrace
126 const int frameskip = (8 + sizeof(void*)) / sizeof(void*);
127 historybt[historyIndex].bt_size = backtrace(historybt[historyIndex].bt - frameskip, MAX_STACK + frameskip) - frameskip;
128 historybt[historyIndex].op = op;
129 historybt[historyIndex].frameNum = gs->frameNum;
130 h = &historybt[historyIndex];
131 }
132 #endif
133
134 if (size == 4) {
135 // common case
136 h->data = *(const unsigned*) p;
137 }
138 else {
139 // > XOR seems dangerous in that every bit is independent of any other, this is bad.
140 // This isn't the case here, however, because typically we checksum only 1-8 bytes
141 // of data at a time, so most of it fits in the checksum anyway.
142 // (see SyncedPrimitiveBase / SyncedPrimitive, the main client of this method)
143 unsigned i = 0;
144 h->data = 0;
145 // whole dwords
146 for (; i < (size & ~3); i += 4)
147 h->data ^= *(const unsigned*) ((const unsigned char*) p + i);
148 // remaining 0 to 3 bytes
149 for (; i < size; ++i)
150 h->data ^= *((const unsigned char*) p + i);
151 }
152
153 if (++historyIndex == HISTORY_SIZE * BLOCK_SIZE) {
154 historyIndex = 0; // wrap around
155 }
156 ++flop;
157 }
158
159
Backtrace(int index,const char * prefix) const160 void CSyncDebugger::Backtrace(int index, const char* prefix) const
161 {
162 if (historybt) {
163 for (unsigned i = 0; i < historybt[index].bt_size; ++i) {
164 // the "{%p}" part is resolved to "functionname [filename:lineno]"
165 // by the CLogger class.
166 #ifndef _WIN32
167 logger.AddLine("%s#%u {%p}", prefix, i, historybt[index].bt[i]);
168 #else
169 if (sizeof(void*) == 8)
170 logger.AddLine("%s#%u {%llx}", prefix, i, (boost::uint64_t)historybt[index].bt[i]);
171 else
172 logger.AddLine("%s#%u {%x}", prefix, i, (boost::uint32_t)historybt[index].bt[i]);
173 #endif
174 }
175 }
176 }
177
178
GetBacktraceChecksum(int index) const179 unsigned CSyncDebugger::GetBacktraceChecksum(int index) const
180 {
181 return HsiehHash((char *)historybt[index].bt, sizeof(void*) * historybt[index].bt_size, 0xf00dcafe);
182 }
183
184
ServerReceived(const unsigned char * inbuf)185 bool CSyncDebugger::ServerReceived(const unsigned char* inbuf)
186 {
187 bool syncDebugPacket = false;
188 switch (inbuf[0]) {
189 case NETMSG_SD_CHKRESPONSE:
190 if (*(short*)&inbuf[1] != HISTORY_SIZE * sizeof(unsigned) + 12) {
191 logger.AddLine("Server: received checksum response of %d instead of %d bytes", *(short*)&inbuf[1], HISTORY_SIZE * 4 + 12);
192 } else {
193 int player = inbuf[3];
194 if (!playerHandler->IsValidPlayer(player)) {
195 logger.AddLine("Server: got invalid playernum %d in checksum response", player);
196 } else {
197 logger.AddLine("Server: got checksum response from %d", player);
198 const unsigned* begin = (unsigned*)&inbuf[12];
199 const unsigned* end = begin + HISTORY_SIZE;
200 players[player].checksumResponses.resize(HISTORY_SIZE);
201 std::copy(begin, end, players[player].checksumResponses.begin());
202 players[player].remoteFlop = *(boost::uint64_t*)&inbuf[4];
203 assert(!players[player].checksumResponses.empty());
204 int i = 0;
205 while (i < playerHandler->ActivePlayers() && !players[i].checksumResponses.empty()) ++i;
206 if (i == playerHandler->ActivePlayers()) {
207 ServerQueueBlockRequests();
208 logger.AddLine("Server: checksum responses received; %d block requests queued", pendingBlocksToRequest.size());
209 }
210 }
211 }
212 syncDebugPacket = true;
213 break;
214 case NETMSG_SD_BLKRESPONSE:
215 if (*(short*)&inbuf[1] != BLOCK_SIZE * sizeof(unsigned) + 4) {
216 logger.AddLine("Server: received block response of %d instead of %d bytes", *(short*)&inbuf[1], BLOCK_SIZE * 4 + 4);
217 } else {
218 int player = inbuf[3];
219 if (!playerHandler->IsValidPlayer(player)) {
220 logger.AddLine("Server: got invalid playernum %d in block response", player);
221 } else {
222 const unsigned* begin = (unsigned*)&inbuf[4];
223 const unsigned* end = begin + BLOCK_SIZE;
224 unsigned size = players[player].remoteHistory.size();
225 players[player].remoteHistory.resize(size + BLOCK_SIZE);
226 std::copy(begin, end, players[player].remoteHistory.begin() + size);
227 int i = 0;
228 size += BLOCK_SIZE;
229 while (i < playerHandler->ActivePlayers() && size == players[i].remoteHistory.size()) ++i;
230 if (i == playerHandler->ActivePlayers()) {
231 logger.AddLine("Server: block responses received");
232 ServerReceivedBlockResponses();
233 }
234 }
235 }
236 syncDebugPacket = true;
237 break;
238 default:
239 logger.AddLine("Server: unknown packet");
240 break;
241 }
242 logger.FlushBuffer();
243 return syncDebugPacket;
244 }
245
246
ClientReceived(const unsigned char * inbuf)247 bool CSyncDebugger::ClientReceived(const unsigned char* inbuf)
248 {
249 bool syncDebugPacket = false;
250 switch (inbuf[0]) {
251 case NETMSG_SD_CHKREQUEST:
252 if (gs->frameNum != *(int*)&inbuf[1]) {
253 logger.AddLine("Client: received checksum request for frame %d instead of %d", *(int*)&inbuf[1], gs->frameNum);
254 } else {
255 disable_history = true; // no more additions to the history until we're done
256 may_enable_history = false;
257 ClientSendChecksumResponse();
258 logger.AddLine("Client: checksum response sent");
259 }
260 syncDebugPacket = true;
261 break;
262 case NETMSG_SD_BLKREQUEST:
263 if (*(unsigned short*)&inbuf[1] >= HISTORY_SIZE) {
264 logger.AddLine("Client: invalid block number %d in block request", *(unsigned short*)&inbuf[1]);
265 } else {
266 ClientSendBlockResponse(*(unsigned short*)&inbuf[1]);
267 logger.AddLine("Client: block response sent for block %d", *(unsigned short*)&inbuf[1]);
268 // simple progress indication
269 LOG("Client: %d / %d", *(unsigned short*)&inbuf[3], *(unsigned short*)&inbuf[5]);
270 }
271 syncDebugPacket = true;
272 break;
273 case NETMSG_SD_RESET:
274 logger.CloseSession();
275 LOG("Client: Done!");
276 // disable_history = false;
277 may_enable_history = true;
278 syncDebugPacket = true;
279 break;
280 }
281 logger.FlushBuffer();
282 return syncDebugPacket;
283 }
284
285
ServerTriggerSyncErrorHandling(int serverframenum)286 void CSyncDebugger::ServerTriggerSyncErrorHandling(int serverframenum)
287 {
288 if (!disable_history) {
289 //this will set disable_history = true once received so only one sync errors is handled at a time.
290 }
291 }
292
293
ClientSendChecksumResponse()294 void CSyncDebugger::ClientSendChecksumResponse()
295 {
296 std::vector<unsigned> checksums;
297 for (unsigned i = 0; i < HISTORY_SIZE; ++i) {
298 unsigned checksum = 123456789;
299 for (unsigned j = 0; j < BLOCK_SIZE; ++j) {
300 if (historybt) {
301 checksum = HsiehHash((char*)&historybt[BLOCK_SIZE * i + j].data, sizeof(historybt[0].data), checksum);
302 } else {
303 checksum = HsiehHash((char*)&history[BLOCK_SIZE * i + j].data, sizeof(history[0].data), checksum);
304 }
305 }
306 checksums.push_back(checksum);
307 }
308 net->Send(CBaseNetProtocol::Get().SendSdCheckresponse(gu->myPlayerNum, flop, checksums));
309 }
310
311
ServerQueueBlockRequests()312 void CSyncDebugger::ServerQueueBlockRequests()
313 {
314 logger.AddLine("Server: queuing block requests");
315 boost::uint64_t correctFlop = 0;
316 for (int j = 0; j < playerHandler->ActivePlayers(); ++j) {
317 if (correctFlop) {
318 if (players[j].remoteFlop != correctFlop)
319 logger.AddLine("Server: bad flop# %llu instead of %llu for player %d", players[j].remoteFlop, correctFlop, j);
320 } else {
321 correctFlop = players[j].remoteFlop;
322 }
323 }
324 unsigned i = ((unsigned)(correctFlop % (HISTORY_SIZE * BLOCK_SIZE)) / BLOCK_SIZE) + 1;
325 for (unsigned c = 0; c < HISTORY_SIZE; ++i, ++c) {
326 unsigned correctChecksum = 0;
327 if (i == HISTORY_SIZE) i = 0;
328 for (int j = 0; j < playerHandler->ActivePlayers(); ++j) {
329 if (correctChecksum && players[j].checksumResponses[i] != correctChecksum) {
330 pendingBlocksToRequest.push_back(i);
331 break;
332 }
333 correctChecksum = players[j].checksumResponses[i];
334 }
335 }
336 if (!pendingBlocksToRequest.empty()) {
337 logger.AddLine("Server: blocks: %u equal, %u not equal", HISTORY_SIZE - pendingBlocksToRequest.size(), pendingBlocksToRequest.size());
338 requestedBlocks = pendingBlocksToRequest;
339 // we know the first FPU bug occured in block # ii, so we send out a block request for it.
340 // serverNet->SendData<unsigned> (NETMSG_SD_BLKREQUEST, ii);
341 } else {
342 logger.AddLine("Server: huh, all blocks equal?!?");
343 net->Send(CBaseNetProtocol::Get().SendSdReset());
344 }
345 //cleanup
346 for (PlayerVec::iterator it = players.begin(); it != players.end(); ++it)
347 it->checksumResponses.clear();
348 logger.FlushBuffer();
349 }
350
351
ServerHandlePendingBlockRequests()352 void CSyncDebugger::ServerHandlePendingBlockRequests()
353 {
354 if (!pendingBlocksToRequest.empty() && !waitingForBlockResponse) {
355 // last two shorts are for progress indication
356 net->Send(CBaseNetProtocol::Get().SendSdBlockrequest(pendingBlocksToRequest.front(), requestedBlocks.size() - pendingBlocksToRequest.size() + 1, requestedBlocks.size()));
357 waitingForBlockResponse = true;
358 }
359 }
360
361
ClientSendBlockResponse(int block)362 void CSyncDebugger::ClientSendBlockResponse(int block)
363 {
364 std::vector<unsigned> checksums;
365 #ifdef TRACE_SYNC
366 tracefile << "Sending block response for block " << block << "\n";
367 #endif
368 for (unsigned i = 0; i < BLOCK_SIZE; ++i) {
369 if (historybt) {
370 checksums.push_back(historybt[BLOCK_SIZE * block + i].data);
371 }
372 else {
373 checksums.push_back(history[BLOCK_SIZE * block + i].data);
374 }
375 #ifdef TRACE_SYNC
376 if (historybt) {
377 tracefile << historybt[BLOCK_SIZE * block + i].data << " " << historybt[BLOCK_SIZE * block + i].data << "\n";
378 }
379 else {
380 tracefile << history[BLOCK_SIZE * block + i].data << " " << history[BLOCK_SIZE * block + i].data << "\n";
381 }
382 #endif
383 }
384 #ifdef TRACE_SYNC
385 tracefile << "done\n";
386 #endif
387 net->Send(CBaseNetProtocol::Get().SendSdBlockresponse(gu->myPlayerNum, checksums));
388 }
389
390
ServerReceivedBlockResponses()391 void CSyncDebugger::ServerReceivedBlockResponses()
392 {
393 pendingBlocksToRequest.pop_front();
394 waitingForBlockResponse = false;
395 // analyse data and reset if this was the last block response
396 if (pendingBlocksToRequest.empty())
397 ServerDumpStack();
398 }
399
400
ServerDumpStack()401 void CSyncDebugger::ServerDumpStack()
402 {
403 // first calculate start iterator...
404 unsigned posInHistory = (unsigned)(players[0].remoteFlop % (HISTORY_SIZE * BLOCK_SIZE));
405 logger.AddLine("Server: position in history: %u", posInHistory);
406 unsigned blockNr = posInHistory / BLOCK_SIZE;
407 unsigned virtualBlockNr = 0; // block nr in remoteHistory (which skips unchanged blocks)
408 for (; virtualBlockNr < requestedBlocks.size() && requestedBlocks[virtualBlockNr] != blockNr; ++virtualBlockNr) {}
409 unsigned virtualPosInHistory = (virtualBlockNr * BLOCK_SIZE) + (posInHistory % BLOCK_SIZE) + 1;
410 unsigned virtualHistorySize = players[0].remoteHistory.size();
411 if (virtualBlockNr >= requestedBlocks.size())
412 virtualPosInHistory = virtualHistorySize;
413 unsigned ndif = 0; // number of differences
414 assert(virtualPosInHistory <= virtualHistorySize);
415
416 // we make a pool of backtraces (to merge identical ones)
417 unsigned curBacktrace = 0;
418 std::map<unsigned, unsigned> checksumToIndex;
419 std::map<unsigned, unsigned> indexToHistPos;
420
421 // then loop from virtualPosInHistory to virtualHistorySize and from 0 to virtualPosInHistory.
422 for (unsigned i = virtualPosInHistory, c = 0; c < virtualHistorySize; ++i, ++c) {
423 unsigned correctChecksum = 0;
424 if (i == virtualHistorySize) i = 0;
425 bool err = false;
426 for (int j = 0; j < playerHandler->ActivePlayers(); ++j) {
427 if (correctChecksum && players[j].remoteHistory[i] != correctChecksum) {
428 if (historybt) {
429 virtualBlockNr = i / BLOCK_SIZE;
430 blockNr = requestedBlocks[virtualBlockNr];
431 unsigned histPos = blockNr * BLOCK_SIZE + i % BLOCK_SIZE;
432 unsigned checksum = GetBacktraceChecksum(histPos);
433 std::map<unsigned, unsigned>::iterator it = checksumToIndex.find(checksum);
434 if (it == checksumToIndex.end()) {
435 ++curBacktrace;
436 checksumToIndex[checksum] = curBacktrace;
437 indexToHistPos[curBacktrace] = histPos;
438 }
439 logger.AddLine("Server: 0x%08X/%15.8e instead of 0x%08X/%15.8e, frame %06u, backtrace %u in \"%s\"",
440 players[j].remoteHistory[i], *(float*)(char*)&players[j].remoteHistory[i],
441 correctChecksum, *(float*)(char*)&correctChecksum,
442 historybt[histPos].frameNum, checksumToIndex[checksum], historybt[histPos].op);
443 } else {
444 logger.AddLine("Server: 0x%08X/%15.8e instead of 0x%08X/%15.8e",
445 players[j].remoteHistory[i], *(float*)(char*)&players[j].remoteHistory[i],
446 correctChecksum, *(float*)(char*)&correctChecksum);
447 }
448 err = true;
449 } else {
450 correctChecksum = players[j].remoteHistory[i];
451 }
452 }
453 if (err) {
454 ++ndif;
455 }
456 }
457 if (ndif)
458 logger.AddLine("Server: chks: %d equal, %d not equal", virtualHistorySize - ndif, ndif);
459 else
460 // This is impossible (internal error).
461 // Server first finds there are differing blocks, then all checksums equal??
462 // Turns out this can happen if the checksum function is weak.
463 logger.AddLine("Server: huh, all checksums equal?!? (INTERNAL ERROR)");
464
465 //cleanup
466 for (PlayerVec::iterator it = players.begin(); it != players.end(); ++it)
467 it->remoteHistory.clear();
468
469 if (historybt) {
470 // output backtraces we collected earlier this function
471 for (std::map<unsigned, unsigned>::iterator it = indexToHistPos.begin(); it != indexToHistPos.end(); ++it) {
472 logger.AddLine("Server: === Backtrace %u ===", it->first);
473 Backtrace(it->second, "Server: ");
474 }
475 }
476
477 // and reset
478 net->Send(CBaseNetProtocol::Get().SendSdReset());
479 logger.AddLine("Server: Done!");
480 logger.CloseSession();
481 LOG("Server: Done!");
482 }
483
484
Reset()485 void CSyncDebugger::Reset()
486 {
487 if (may_enable_history)
488 disable_history = false;
489 }
490
491 #endif // SYNCDEBUG
492