newnet: Send CRCs of syncDebug strings, not the strings themselves.
syncDebug should now be useful, even over a slow network.master
Cyp
parent
115146146b
commit
bfb9250937
|
|
@ -58,6 +58,9 @@ static SDWORD pauseStart;
|
|||
static UDWORD stopCount;
|
||||
|
||||
static uint32_t gameQueueTime[MAX_PLAYERS];
|
||||
static uint32_t gameQueueCheckTime[MAX_PLAYERS];
|
||||
static uint32_t gameQueueCheckCrc[MAX_PLAYERS];
|
||||
static bool crcError = false;
|
||||
|
||||
/* Initialise the game clock */
|
||||
void gameTimeInit(void)
|
||||
|
|
@ -170,6 +173,13 @@ void gameTimeUpdate()
|
|||
}
|
||||
|
||||
deltaGameTime = GAME_TICKS_PER_UPDATE;
|
||||
|
||||
if (crcError)
|
||||
{
|
||||
debug(LOG_ERROR, "Synch error, gameTimes were: {%10u, %10u, %10u, %10u, %10u, %10u, %10u, %10u}", gameQueueCheckTime[0], gameQueueCheckTime[1], gameQueueCheckTime[2], gameQueueCheckTime[3], gameQueueCheckTime[4], gameQueueCheckTime[5], gameQueueCheckTime[6], gameQueueCheckTime[7]);
|
||||
debug(LOG_ERROR, "Synch error, CRCs were: {0x%08X, 0x%08X, 0x%08X, 0x%08X, 0x%08X, 0x%08X, 0x%08X, 0x%08X}", gameQueueCheckCrc[0], gameQueueCheckCrc[1], gameQueueCheckCrc[2], gameQueueCheckCrc[3], gameQueueCheckCrc[4], gameQueueCheckCrc[5], gameQueueCheckCrc[6], gameQueueCheckCrc[7]);
|
||||
crcError = false;
|
||||
}
|
||||
}
|
||||
else
|
||||
{
|
||||
|
|
@ -305,8 +315,8 @@ void sendPlayerGameTime()
|
|||
|
||||
unsigned player;
|
||||
uint32_t time = gameTime + latency;
|
||||
|
||||
sendDebugSync(true);
|
||||
uint32_t checkTime = gameTime;
|
||||
uint32_t checkCrc = nextDebugSync();
|
||||
|
||||
for (player = 0; player < MAX_PLAYERS; ++player)
|
||||
{
|
||||
|
|
@ -317,19 +327,32 @@ void sendPlayerGameTime()
|
|||
|
||||
NETbeginEncode(NETgameQueue(player), GAME_GAME_TIME);
|
||||
NETuint32_t(&time);
|
||||
NETuint32_t(&checkTime);
|
||||
NETuint32_t(&checkCrc);
|
||||
NETend();
|
||||
}
|
||||
}
|
||||
|
||||
void recvPlayerGameTime(NETQUEUE queue)
|
||||
{
|
||||
uint32_t time;
|
||||
uint32_t time = 0;
|
||||
uint32_t checkTime = 0;
|
||||
uint32_t checkCrc = 0;
|
||||
|
||||
NETbeginDecode(queue, GAME_GAME_TIME);
|
||||
NETuint32_t(&time);
|
||||
NETuint32_t(&checkTime);
|
||||
NETuint32_t(&checkCrc);
|
||||
NETend();
|
||||
|
||||
gameQueueTime[queue.index] = time;
|
||||
|
||||
gameQueueCheckTime[queue.index] = checkTime;
|
||||
gameQueueCheckCrc[queue.index] = checkCrc;
|
||||
if (!checkDebugSync(checkTime, checkCrc))
|
||||
{
|
||||
crcError = true;
|
||||
}
|
||||
}
|
||||
|
||||
bool checkPlayerGameTime(unsigned player)
|
||||
|
|
|
|||
|
|
@ -3856,14 +3856,31 @@ unsigned int NETgetGameserverPort()
|
|||
}
|
||||
|
||||
#define MAX_LEN_LOG_LINE 512 // From debug.c - no use printing something longer.
|
||||
#define MAX_SYNC_MESSAGES 1000
|
||||
#define MAX_SYNC_HISTORY 100
|
||||
#define MAX_SYNC_MESSAGES 10000
|
||||
#define MAX_SYNC_HISTORY 10
|
||||
|
||||
static uint32_t crcSum(uint32_t crc, const char *data, size_t dataLen)
|
||||
{
|
||||
const uint32_t crcTable[256] = {0x00000000, 0x04C11DB7, 0x09823B6E, 0x0D4326D9, 0x130476DC, 0x17C56B6B, 0x1A864DB2, 0x1E475005, 0x2608EDB8, 0x22C9F00F, 0x2F8AD6D6, 0x2B4BCB61, 0x350C9B64, 0x31CD86D3, 0x3C8EA00A, 0x384FBDBD, 0x4C11DB70, 0x48D0C6C7, 0x4593E01E, 0x4152FDA9, 0x5F15ADAC, 0x5BD4B01B, 0x569796C2, 0x52568B75, 0x6A1936C8, 0x6ED82B7F, 0x639B0DA6, 0x675A1011, 0x791D4014, 0x7DDC5DA3, 0x709F7B7A, 0x745E66CD, 0x9823B6E0, 0x9CE2AB57, 0x91A18D8E, 0x95609039, 0x8B27C03C, 0x8FE6DD8B, 0x82A5FB52, 0x8664E6E5, 0xBE2B5B58, 0xBAEA46EF, 0xB7A96036, 0xB3687D81, 0xAD2F2D84, 0xA9EE3033, 0xA4AD16EA, 0xA06C0B5D, 0xD4326D90, 0xD0F37027, 0xDDB056FE, 0xD9714B49, 0xC7361B4C, 0xC3F706FB, 0xCEB42022, 0xCA753D95, 0xF23A8028, 0xF6FB9D9F, 0xFBB8BB46, 0xFF79A6F1, 0xE13EF6F4, 0xE5FFEB43, 0xE8BCCD9A, 0xEC7DD02D, 0x34867077, 0x30476DC0, 0x3D044B19, 0x39C556AE, 0x278206AB, 0x23431B1C, 0x2E003DC5, 0x2AC12072, 0x128E9DCF, 0x164F8078, 0x1B0CA6A1, 0x1FCDBB16, 0x018AEB13, 0x054BF6A4, 0x0808D07D, 0x0CC9CDCA, 0x7897AB07, 0x7C56B6B0, 0x71159069, 0x75D48DDE, 0x6B93DDDB, 0x6F52C06C, 0x6211E6B5, 0x66D0FB02, 0x5E9F46BF, 0x5A5E5B08, 0x571D7DD1, 0x53DC6066, 0x4D9B3063, 0x495A2DD4, 0x44190B0D, 0x40D816BA, 0xACA5C697, 0xA864DB20, 0xA527FDF9, 0xA1E6E04E, 0xBFA1B04B, 0xBB60ADFC, 0xB6238B25, 0xB2E29692, 0x8AAD2B2F, 0x8E6C3698, 0x832F1041, 0x87EE0DF6, 0x99A95DF3, 0x9D684044, 0x902B669D, 0x94EA7B2A, 0xE0B41DE7, 0xE4750050, 0xE9362689, 0xEDF73B3E, 0xF3B06B3B, 0xF771768C, 0xFA325055, 0xFEF34DE2, 0xC6BCF05F, 0xC27DEDE8, 0xCF3ECB31, 0xCBFFD686, 0xD5B88683, 0xD1799B34, 0xDC3ABDED, 0xD8FBA05A, 0x690CE0EE, 0x6DCDFD59, 0x608EDB80, 0x644FC637, 0x7A089632, 0x7EC98B85, 0x738AAD5C, 0x774BB0EB, 0x4F040D56, 0x4BC510E1, 0x46863638, 0x42472B8F, 0x5C007B8A, 0x58C1663D, 0x558240E4, 0x51435D53, 0x251D3B9E, 0x21DC2629, 0x2C9F00F0, 0x285E1D47, 0x36194D42, 0x32D850F5, 0x3F9B762C, 0x3B5A6B9B, 0x0315D626, 0x07D4CB91, 0x0A97ED48, 0x0E56F0FF, 0x1011A0FA, 0x14D0BD4D, 0x19939B94, 0x1D528623, 0xF12F560E, 0xF5EE4BB9, 0xF8AD6D60, 0xFC6C70D7, 0xE22B20D2, 0xE6EA3D65, 0xEBA91BBC, 0xEF68060B, 0xD727BBB6, 0xD3E6A601, 0xDEA580D8, 0xDA649D6F, 0xC423CD6A, 0xC0E2D0DD, 0xCDA1F604, 0xC960EBB3, 0xBD3E8D7E, 0xB9FF90C9, 0xB4BCB610, 0xB07DABA7, 0xAE3AFBA2, 0xAAFBE615, 0xA7B8C0CC, 0xA379DD7B, 0x9B3660C6, 0x9FF77D71, 0x92B45BA8, 0x9675461F, 0x8832161A, 0x8CF30BAD, 0x81B02D74, 0x857130C3, 0x5D8A9099, 0x594B8D2E, 0x5408ABF7, 0x50C9B640, 0x4E8EE645, 0x4A4FFBF2, 0x470CDD2B, 0x43CDC09C, 0x7B827D21, 0x7F436096, 0x7200464F, 0x76C15BF8, 0x68860BFD, 0x6C47164A, 0x61043093, 0x65C52D24, 0x119B4BE9, 0x155A565E, 0x18197087, 0x1CD86D30, 0x029F3D35, 0x065E2082, 0x0B1D065B, 0x0FDC1BEC, 0x3793A651, 0x3352BBE6, 0x3E119D3F, 0x3AD08088, 0x2497D08D, 0x2056CD3A, 0x2D15EBE3, 0x29D4F654, 0xC5A92679, 0xC1683BCE, 0xCC2B1D17, 0xC8EA00A0, 0xD6AD50A5, 0xD26C4D12, 0xDF2F6BCB, 0xDBEE767C, 0xE3A1CBC1, 0xE760D676, 0xEA23F0AF, 0xEEE2ED18, 0xF0A5BD1D, 0xF464A0AA, 0xF9278673, 0xFDE69BC4, 0x89B8FD09, 0x8D79E0BE, 0x803AC667, 0x84FBDBD0, 0x9ABC8BD5, 0x9E7D9662, 0x933EB0BB, 0x97FFAD0C, 0xAFB010B1, 0xAB710D06, 0xA6322BDF, 0xA2F33668, 0xBCB4666D, 0xB8757BDA, 0xB5365D03, 0xB1F740B4};
|
||||
// Invariant:
|
||||
// crcTable[0] = 0;
|
||||
// crcTable[1] = 0x04C11DB7;
|
||||
// crcTable[i] = crcTable[i>>1]<<1 ^ ((crcTable[i>>1]>>31 ^ (i & 0x01))*crcTable[1]);
|
||||
|
||||
while (dataLen-- > 0)
|
||||
{
|
||||
crc = crc<<8 ^ crcTable[crc>>24 ^ (uint8_t)*data++];
|
||||
}
|
||||
|
||||
return crc;
|
||||
}
|
||||
|
||||
static unsigned syncDebugNext = 0;
|
||||
static uint32_t syncDebugNum[MAX_SYNC_HISTORY];
|
||||
static uint32_t syncDebugGameTime[MAX_SYNC_HISTORY];
|
||||
static char *syncDebugFunctions[MAX_SYNC_HISTORY][MAX_SYNC_MESSAGES];
|
||||
static char *syncDebugStrings[MAX_SYNC_HISTORY][MAX_SYNC_MESSAGES];
|
||||
static uint32_t syncDebugCrcs[MAX_SYNC_HISTORY];
|
||||
|
||||
void _syncDebug(const char *function, const char *str, ...)
|
||||
{
|
||||
|
|
@ -3878,6 +3895,8 @@ void _syncDebug(const char *function, const char *str, ...)
|
|||
{
|
||||
syncDebugFunctions[syncDebugNext][syncDebugNum[syncDebugNext]] = strdup(function);
|
||||
syncDebugStrings[syncDebugNext][syncDebugNum[syncDebugNext]] = strdup(outputBuffer);
|
||||
syncDebugCrcs[syncDebugNext] = crcSum(syncDebugCrcs[syncDebugNext], function, strlen(function) + 1);
|
||||
syncDebugCrcs[syncDebugNext] = crcSum(syncDebugCrcs[syncDebugNext], outputBuffer, strlen(outputBuffer) + 1);
|
||||
++syncDebugNum[syncDebugNext];
|
||||
}
|
||||
}
|
||||
|
|
@ -3899,101 +3918,70 @@ void syncDebugBacktrace(void)
|
|||
#endif
|
||||
}
|
||||
|
||||
void sendDebugSync(bool sendEvenIfEmpty)
|
||||
uint32_t nextDebugSync(void)
|
||||
{
|
||||
uint32_t ret = ~syncDebugCrcs[syncDebugNext]; // Invert bits, since everyone else seems to do that with CRCs...
|
||||
unsigned i;
|
||||
|
||||
if (syncDebugNum[syncDebugNext] == 0 && !sendEvenIfEmpty)
|
||||
{
|
||||
return; // Nothing to send.
|
||||
}
|
||||
|
||||
// Save gameTime, so we know which CRC to compare with, later.
|
||||
syncDebugGameTime[syncDebugNext] = gameTime;
|
||||
|
||||
NETbeginEncode(NETgameQueue(selectedPlayer), GAME_SYNC_DEBUG_STRING);
|
||||
NETuint32_t(&syncDebugNum[syncDebugNext]);
|
||||
NETuint32_t(&syncDebugGameTime[syncDebugNext]);
|
||||
for (i = 0; i < syncDebugNum[syncDebugNext]; ++i)
|
||||
{
|
||||
NETstring(syncDebugFunctions[syncDebugNext][i], MAX_LEN_LOG_LINE);
|
||||
NETstring(syncDebugStrings[syncDebugNext][i], MAX_LEN_LOG_LINE);
|
||||
}
|
||||
NETend();
|
||||
|
||||
// Go to next position, and free it ready for use.
|
||||
syncDebugNext = (syncDebugNext + 1)%MAX_SYNC_HISTORY;
|
||||
for (unsigned i = 0; i != syncDebugNum[syncDebugNext]; ++i)
|
||||
for (i = 0; i != syncDebugNum[syncDebugNext]; ++i)
|
||||
{
|
||||
free(syncDebugFunctions[syncDebugNext][i]);
|
||||
free(syncDebugStrings[syncDebugNext][i]);
|
||||
}
|
||||
syncDebugNum[syncDebugNext] = 0;
|
||||
syncDebugGameTime[syncDebugNext] = 0;
|
||||
syncDebugCrcs[syncDebugNext] = 0x00000000;
|
||||
|
||||
return ret;
|
||||
}
|
||||
|
||||
void recvDebugSync(NETQUEUE queue)
|
||||
bool checkDebugSync(uint32_t checkGameTime, uint32_t checkCrc)
|
||||
{
|
||||
bool outOfSynch = false;
|
||||
unsigned rsyncDebugNext;
|
||||
unsigned index;
|
||||
unsigned i;
|
||||
|
||||
uint32_t rsyncDebugNum;
|
||||
uint32_t rsyncDebugGameTime;
|
||||
char rsyncDebugFunction[MAX_LEN_LOG_LINE];
|
||||
char rsyncDebugString[MAX_LEN_LOG_LINE];
|
||||
|
||||
NETbeginDecode(queue, GAME_SYNC_DEBUG_STRING);
|
||||
NETuint32_t(&rsyncDebugNum);
|
||||
NETuint32_t(&rsyncDebugGameTime);
|
||||
|
||||
if (rsyncDebugGameTime == syncDebugGameTime[syncDebugNext])
|
||||
{
|
||||
debug(LOG_ERROR, "Huh? We aren't done yet...");
|
||||
NETend();
|
||||
return;
|
||||
}
|
||||
|
||||
for (rsyncDebugNext = 0; rsyncDebugNext != MAX_SYNC_HISTORY; ++rsyncDebugNext)
|
||||
{
|
||||
if (syncDebugGameTime[rsyncDebugNext] == rsyncDebugGameTime)
|
||||
{
|
||||
unsigned i;
|
||||
|
||||
if (syncDebugNum[rsyncDebugNext] != rsyncDebugNum)
|
||||
{
|
||||
outOfSynch = true;
|
||||
}
|
||||
|
||||
for (i = 0; i < syncDebugNum[rsyncDebugNext] && !outOfSynch; ++i)
|
||||
{
|
||||
NETstring(rsyncDebugFunction, MAX_LEN_LOG_LINE);
|
||||
NETstring(rsyncDebugString, MAX_LEN_LOG_LINE);
|
||||
|
||||
if (strcmp(syncDebugFunctions[rsyncDebugNext][i], rsyncDebugFunction) != 0 ||
|
||||
strcmp(syncDebugStrings[rsyncDebugNext][i], rsyncDebugString) != 0)
|
||||
{
|
||||
outOfSynch = true;
|
||||
}
|
||||
}
|
||||
|
||||
break;
|
||||
}
|
||||
}
|
||||
NETend();
|
||||
|
||||
if (outOfSynch)
|
||||
if (checkGameTime == syncDebugGameTime[syncDebugNext]) // Can't happen - and syncDebugGameTime[] == 0, until just before sending the CRC, anyway.
|
||||
{
|
||||
unsigned i;
|
||||
|
||||
debug(LOG_ERROR, "Inconsistent GAME_SYNC_DEBUG_STRING at gameTime %u. My version is: (%u lines)", syncDebugGameTime[rsyncDebugNext], syncDebugNum[rsyncDebugNext]);
|
||||
for (i = 0; i < syncDebugNum[rsyncDebugNext]; ++i)
|
||||
{
|
||||
_debug(LOG_SYNC, syncDebugFunctions[rsyncDebugNext][i], "[%03u] %s", i, syncDebugStrings[rsyncDebugNext][i]);
|
||||
free(syncDebugFunctions[rsyncDebugNext][i]);
|
||||
free(syncDebugStrings[rsyncDebugNext][i]);
|
||||
}
|
||||
syncDebugNum[rsyncDebugNext] = 0;
|
||||
syncDebugGameTime[rsyncDebugNext] = 0;
|
||||
debug(LOG_ERROR, "Huh? We aren't done yet...");
|
||||
return true;
|
||||
}
|
||||
|
||||
for (index = 0; index != MAX_SYNC_HISTORY; ++index)
|
||||
{
|
||||
if (syncDebugGameTime[index] == checkGameTime)
|
||||
{
|
||||
if (~syncDebugCrcs[index] == checkCrc) // Invert bits, since everyone else seems to do that with CRCs...
|
||||
{
|
||||
return true; // Check passed. (So far... There might still be more players to compare CRCs with.)
|
||||
}
|
||||
|
||||
break; // Check failed!
|
||||
}
|
||||
}
|
||||
|
||||
if (index == MAX_SYNC_HISTORY)
|
||||
{
|
||||
return true; // Couldn't check. May have dumped already.
|
||||
}
|
||||
|
||||
// Dump our version, and also erase it, so we only dump it at most once.
|
||||
debug(LOG_ERROR, "Inconsistent sync debug at gameTime %u. My version is: (%u lines, CRC = 0x%08X)", syncDebugGameTime[index], syncDebugNum[index], ~syncDebugCrcs[index] & 0xFFFFFFFF);
|
||||
for (i = 0; i < syncDebugNum[index]; ++i)
|
||||
{
|
||||
_debug(LOG_SYNC, syncDebugFunctions[index][i], "[%03u] %s", i, syncDebugStrings[index][i]);
|
||||
free(syncDebugFunctions[index][i]);
|
||||
free(syncDebugStrings[index][i]);
|
||||
}
|
||||
syncDebugNum[index] = 0;
|
||||
syncDebugGameTime[index] = 0;
|
||||
syncDebugCrcs[index] = 0x00000000;
|
||||
|
||||
return false; // Ouch.
|
||||
}
|
||||
|
||||
const char *messageTypeToString(unsigned messageType_)
|
||||
|
|
@ -4067,7 +4055,6 @@ const char *messageTypeToString(unsigned messageType_)
|
|||
case GAME_STRUCTUREINFO: return "GAME_STRUCTUREINFO";
|
||||
case GAME_LASSAT: return "GAME_LASSAT";
|
||||
case GAME_GAME_TIME: return "GAME_GAME_TIME";
|
||||
case GAME_SYNC_DEBUG_STRING: return "GAME_SYNC_DEBUG_STRING";
|
||||
case GAME_MAX_TYPE: return "GAME_MAX_TYPE";
|
||||
}
|
||||
return "(INVALID MESSAGE TYPE)";
|
||||
|
|
|
|||
|
|
@ -113,7 +113,6 @@ typedef enum
|
|||
GAME_STRUCTUREINFO, ///< Structure state.
|
||||
GAME_LASSAT, ///< lassat firing.
|
||||
GAME_GAME_TIME, ///< Game time. Used for synchronising, so that all messages are executed at the same gameTime on all clients.
|
||||
GAME_SYNC_DEBUG_STRING, ///< For debugging purposes only. For checking if all clients do the same syncDebug() calls.
|
||||
GAME_MAX_TYPE ///< Maximum+1 valid GAME_ type, *MUST* be last.
|
||||
} MESSAGE_TYPES;
|
||||
|
||||
|
|
@ -320,13 +319,14 @@ extern void NET_InitPlayers(void);
|
|||
|
||||
const char *messageTypeToString(unsigned messageType);
|
||||
|
||||
/// Sync debugging. Only prints anything, if different players do different calls. Doesn't print anything, if all players that do the same calls get the same result, even if some players don't do any calls.
|
||||
/// Sync debugging. Only prints anything, if different players would print different things.
|
||||
#define syncDebug(...) do { _syncDebug(__FUNCTION__, __VA_ARGS__); } while(0)
|
||||
void _syncDebug(const char *function, const char *str, ...)
|
||||
WZ_DECL_FORMAT(printf, 2, 3);
|
||||
void syncDebugBacktrace(void); ///< Adds a backtrace to syncDebug. (Expect lots of false positives, if all clients aren't using the exact same binaries.)
|
||||
void sendDebugSync(bool sendEvenIfEmpty);
|
||||
void recvDebugSync(NETQUEUE queue);
|
||||
|
||||
uint32_t nextDebugSync(void); ///< Returns a CRC corresponding to all syncDebug() calls since the last nextDebugSync() call.
|
||||
bool checkDebugSync(uint32_t checkGameTime, uint32_t checkCrc); ///< Dumps all syncDebug() calls from that gameTime, if the CRC doesn't match.
|
||||
|
||||
#ifdef __cplusplus
|
||||
}
|
||||
|
|
|
|||
|
|
@ -583,6 +583,11 @@ BOOL recvMessage(void)
|
|||
bool processedMessage1 = false;
|
||||
bool processedMessage2 = false;
|
||||
|
||||
if (queue.queueType == QUEUE_GAME)
|
||||
{
|
||||
syncDebug("Processing player %d, message %s", queue.index, messageTypeToString(type));
|
||||
}
|
||||
|
||||
if (queue.queueType == QUEUE_GAME && myResponsibility(queue.index))
|
||||
{
|
||||
switch (type)
|
||||
|
|
@ -824,9 +829,6 @@ BOOL recvMessage(void)
|
|||
case NET_PLAYER_STATS:
|
||||
recvMultiStats(queue);
|
||||
break;
|
||||
case GAME_SYNC_DEBUG_STRING:
|
||||
recvDebugSync(queue);
|
||||
break;
|
||||
default:
|
||||
processedMessage2 = false;
|
||||
break;
|
||||
|
|
|
|||
Loading…
Reference in New Issue