From 81af460cfea7b04da884207646172f5eca93122f Mon Sep 17 00:00:00 2001 From: Meep-Eep Date: Thu, 1 Feb 2007 21:57:09 +0000 Subject: [PATCH] More netplay debug code. git-svn-id: svn://svn.code.sf.net/p/sc2/code/trunk@2693 8092fc87-c524-0410-9efc-e669fe64eaf9 --- sc2/ChangeLog | 1 + sc2/src/sc2code/netplay/checksum.c | 39 +++++++------- sc2/src/sc2code/netplay/checksum.h | 1 + sc2/src/sc2code/netplay/crc.c | 11 ++-- sc2/src/sc2code/netplay/crc.h | 19 +++++-- sc2/src/sc2code/netplay/netconnection.c | 68 ++++++++++++++++++++++++- sc2/src/sc2code/netplay/netconnection.h | 18 ++++++- sc2/src/sc2code/netplay/netplay.h | 9 ++++ 8 files changed, 134 insertions(+), 32 deletions(-) diff --git a/sc2/ChangeLog b/sc2/ChangeLog index 6ee843fec..71fe3b1d5 100644 --- a/sc2/ChangeLog +++ b/sc2/ChangeLog @@ -1,4 +1,5 @@ Changes towards version 0.7: +- Added more netplay debug code - SvdB - Added uio_fprintf() and uio_vfprintf() - SvdB - Any input will register for at least one frame (Bug #864) - Michael - Many VControl cleanups - Michael diff --git a/sc2/src/sc2code/netplay/checksum.c b/sc2/src/sc2code/netplay/checksum.c index 78237ec28..871e26ec9 100644 --- a/sc2/src/sc2code/netplay/checksum.c +++ b/sc2/src/sc2code/netplay/checksum.c @@ -32,25 +32,24 @@ #include "libs/mathlib.h" #include "libs/misc.h" - ChecksumBuffer localChecksumBuffer; void crc_processEXTENT(crc_State *state, const EXTENT *val) { #ifdef DUMP_CRC_OPS - log_add(log_Debug, "START crc_processEXTENT()."); + crc_log("START crc_processEXTENT()."); #endif crc_processCOORD(state, val->width); crc_processCOORD(state, val->height); #ifdef DUMP_CRC_OPS - log_add(log_Debug, "END crc_processEXTENT()."); + crc_log("END crc_processEXTENT()."); #endif } void crc_processVELOCITY_DESC(crc_State *state, const VELOCITY_DESC *val) { #ifdef DUMP_CRC_OPS - log_add(log_Debug, "START crc_processVELOCITY_DESC()."); + crc_log("START crc_processVELOCITY_DESC()."); #endif crc_processCOUNT(state, val->TravelAngle); crc_processEXTENT(state, &val->vector); @@ -58,19 +57,19 @@ crc_processVELOCITY_DESC(crc_State *state, const VELOCITY_DESC *val) { crc_processEXTENT(state, &val->error); crc_processEXTENT(state, &val->incr); #ifdef DUMP_CRC_OPS - log_add(log_Debug, "END crc_processVELOCITY_DESC()."); + crc_log("END crc_processVELOCITY_DESC()."); #endif } void crc_processPOINT(crc_State *state, const POINT *val) { #ifdef DUMP_CRC_OPS - log_add(log_Debug, "START crc_processPOINT()."); + crc_log("START crc_processPOINT()."); #endif crc_processCOORD(state, val->x); crc_processCOORD(state, val->y); #ifdef DUMP_CRC_OPS - log_add(log_Debug, "END crc_processPOINT()."); + crc_log("END crc_processPOINT()."); #endif } @@ -78,24 +77,24 @@ crc_processPOINT(crc_State *state, const POINT *val) { void crc_processSTAMP(crc_State *state, const STAMP *val) { #ifdef DUMP_CRC_OPS - log_add(log_Debug, "START crc_processSTAMP()."); + crc_log("START crc_processSTAMP()."); #endif crc_processPOINT(state, val->origin); crc_processFRAME(state, val->frame); #ifdef DUMP_CRC_OPS - log_add(log_Debug, "END crc_processSTAMP()."); + crc_log("END crc_processSTAMP()."); #endif } void crc_processINTERSECT_CONTROL(crc_State *state, const INTERSECT_CONTROL *val) { #ifdef DUMP_CRC_OPS - log_add(log_Debug, "START crc_processINTERSECT_CONTROL()."); + crc_log("START crc_processINTERSECT_CONTROL()."); #endif crc_processTIME_VALUE(state, val->last_time_val); crc_processPOINT(state, &val->EndPoint); #ifdef DUMP_CRC_OPS - log_add(log_Debug, "END crc_processINTERSECT_CONTROL()."); + crc_log("END crc_processINTERSECT_CONTROL()."); #endif } #endif @@ -108,7 +107,7 @@ crc_processSTATE(crc_State *state, const STATE *val) { void crc_processELEMENT(crc_State *state, const ELEMENT *val) { #ifdef DUMP_CRC_OPS - log_add(log_Debug, "START crc_processELEMENT()."); + crc_log("START crc_processELEMENT()."); #endif crc_processELEMENT_FLAGS(state, val->state_flags); crc_processCOUNT(state, val->life_span); @@ -133,7 +132,7 @@ crc_processELEMENT(crc_State *state, const ELEMENT *val) { crc_processSTATE(state, &val->current); crc_processSTATE(state, &val->next); #ifdef DUMP_CRC_OPS - log_add(log_Debug, "END crc_processELEMENT()."); + crc_log("END crc_processELEMENT()."); #endif } @@ -144,13 +143,13 @@ crc_processDispQueue(crc_State *state) { #ifdef DUMP_CRC_OPS size_t i = 0; - log_add(log_Debug, "START crc_processDispQueue()."); + crc_log("START crc_processDispQueue()."); #endif for (element = GetHeadElement(); element != 0; element = nextElement) { ELEMENTPTR elementPtr; #ifdef DUMP_CRC_OPS - log_add(log_Debug, "===== disp_q[%d]:", i); + crc_log("===== disp_q[%d]:", i); #endif LockElement(element, &elementPtr); @@ -163,7 +162,7 @@ crc_processDispQueue(crc_State *state) { #endif } #ifdef DUMP_CRC_OPS - log_add(log_Debug, "END crc_processDispQueue()."); + crc_log("END crc_processDispQueue()."); #endif } @@ -172,7 +171,7 @@ crc_processRNG(crc_State *state) { DWORD seed; #ifdef DUMP_CRC_OPS - log_add(log_Debug, "START crc_processRNG()."); + crc_log("START crc_processRNG()."); #endif seed = TFB_SeedRandom(0); @@ -182,14 +181,14 @@ crc_processRNG(crc_State *state) { // Restore the old seed. #ifdef DUMP_CRC_OPS - log_add(log_Debug, "END crc_processRNG()."); + crc_log("END crc_processRNG()."); #endif } void crc_processState(crc_State *state) { #ifdef DUMP_CRC_OPS - log_add(log_Debug, "--------------------\n" + crc_log("--------------------\n" "START crc_processState() (frame %u).", battleFrameCount); #endif @@ -197,7 +196,7 @@ crc_processState(crc_State *state) { crc_processDispQueue(state); #ifdef DUMP_CRC_OPS - log_add(log_Debug, "END crc_processState() (frame %u).", + crc_log("END crc_processState() (frame %u).", battleFrameCount); #endif } diff --git a/sc2/src/sc2code/netplay/checksum.h b/sc2/src/sc2code/netplay/checksum.h index 3cbec4377..d3e4a3572 100644 --- a/sc2/src/sc2code/netplay/checksum.h +++ b/sc2/src/sc2code/netplay/checksum.h @@ -25,6 +25,7 @@ typedef uint32 Checksum; +#include "netplay.h" #include "crc.h" #include "element.h" diff --git a/sc2/src/sc2code/netplay/crc.c b/sc2/src/sc2code/netplay/crc.c index 84a5ae424..677b36f3d 100644 --- a/sc2/src/sc2code/netplay/crc.c +++ b/sc2/src/sc2code/netplay/crc.c @@ -16,6 +16,9 @@ * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA */ +#include "netplay.h" + // For DUMP_CRC_OPS + #include "crc.h" #ifdef DUMP_CRC_OPS @@ -84,7 +87,7 @@ crc_processBytes(crc_State *state, uint8 *buf, size_t bufLen) { newCrc = (newCrc >> 8) ^ crcTable[(newCrc ^ *buf) & 0xff]; #ifdef DUMP_CRC_OPS - log_add(log_Debug, "crc_processBytes(%08x, [%zu bytes]) --> %08x.", + crc_log("crc_processBytes(%08x, [%zu bytes]) --> %08x.", state->crc, bufLen, newCrc); #endif state->crc = newCrc; @@ -96,7 +99,7 @@ crc_processUint8(crc_State *state, uint8 val) { newCrc = (newCrc >> 8) ^ crcTable[(newCrc ^ val) & 0xff]; #ifdef DUMP_CRC_OPS - log_add(log_Debug, "crc_processUint8(%08x, %02x) --> %08x.", + crc_log("crc_processUint8(%08x, %02x) --> %08x.", state->crc, (int) val, newCrc); #endif state->crc = newCrc; @@ -109,7 +112,7 @@ crc_processUint16(crc_State *state, uint16 val) { newCrc = (newCrc >> 8) ^ crcTable[(newCrc ^ (val & 0xff)) & 0xff]; newCrc = (newCrc >> 8) ^ crcTable[(newCrc ^ (val >> 8) ) & 0xff]; #ifdef DUMP_CRC_OPS - log_add(log_Debug, "crc_processUint16(%08x, %04x) --> %08x.", + crc_log("crc_processUint16(%08x, %04x) --> %08x.", state->crc, (int) val, newCrc); #endif state->crc = newCrc; @@ -125,7 +128,7 @@ crc_processUint32(crc_State *state, uint32 val) { newCrc = (newCrc >> 8) ^ crcTable[(newCrc ^ ((val >> 24) )) & 0xff]; #ifdef DUMP_CRC_OPS - log_add(log_Debug, "crc_processUint32(%08x, %08x) --> %08x.", + crc_log("crc_processUint32(%08x, %08x) --> %08x.", state->crc, (int) val, newCrc); #endif state->crc = newCrc; diff --git a/sc2/src/sc2code/netplay/crc.h b/sc2/src/sc2code/netplay/crc.h index 772200139..c1847cf19 100644 --- a/sc2/src/sc2code/netplay/crc.h +++ b/sc2/src/sc2code/netplay/crc.h @@ -19,15 +19,12 @@ #ifndef _CRC_H #define _CRC_H +typedef struct crc_State crc_State; + #include "types.h" #include -// If set, every CRC operation is logged. Very spammy. -#undef DUMP_CRC_OPS - - -typedef struct crc_State crc_State; struct crc_State { uint32 crc; }; @@ -40,5 +37,17 @@ void crc_processUint32(crc_State *state, uint32 val); uint32 crc_finish(const crc_State *state); +#ifdef DUMP_CRC_OPS +#include "netconnection.h" + // for netplayDebugFile +//#define crc_log(...) log_add (logDebug, __VA_ARGS__) +#define crc_log(...) if (netplayDebugFile != NULL) \ + { \ + uio_fprintf (netplayDebugFile, __VA_ARGS__); \ + uio_putc ('\n', netplayDebugFile); \ + } else \ + (void) 0 +#endif + #endif /* _CRC_H */ diff --git a/sc2/src/sc2code/netplay/netconnection.c b/sc2/src/sc2code/netplay/netconnection.c index 44e1be47b..1c99c3475 100644 --- a/sc2/src/sc2code/netplay/netconnection.c +++ b/sc2/src/sc2code/netplay/netconnection.c @@ -25,9 +25,17 @@ #if defined(DEBUG) || defined(NETPLAY_DEBUG) # include "libs/log.h" #endif +#if defined(NETPLAY_DEBUG) && defined(NETPLAY_DEBUG_FILE) +# include "options.h" + // for configDir +#endif #include #include +#if defined(NETPLAY_DEBUG) && defined(NETPLAY_DEBUG_FILE) +# include +# include +#endif static void closeCallback(NetDescriptor *nd); @@ -36,6 +44,9 @@ static void NetConnection_doClose(NetConnection *conn); #include "nc_connect.ci" +#if defined(NETPLAY_DEBUG) && defined(NETPLAY_DEBUG_FILE) +uio_Stream *netplayDebugFile; +#endif // Used as initial value for Agreement structures, by structure assignment. const Agreement Agreement_nothingAgreed; @@ -53,6 +64,49 @@ NetConnection_open(int player, const NetplayPeerOptions *options, conn = malloc(sizeof (NetConnection)); +#if defined(NETPLAY_DEBUG) && defined(NETPLAY_DEBUG_FILE) + { + char dumpFileName[PATH_MAX]; + time_t now; + struct tm *nowTm; + size_t strftimeResult; + + now = time (NULL); + if (now == (time_t) -1) { + log_add (log_Fatal, "time() failed: %s.", strerror (errno)); + abort (); + } + + nowTm = localtime(&now); + // XXX: I would like to use localtime_r(), but it isn't very + // portable (yet), and adding a check for it to the build.sh script + // is not worth the effort for a debugging function right now. + + strftimeResult = strftime (dumpFileName, sizeof dumpFileName, + "debug/netlog-%Y%m%d%H%M%S", nowTm); + if (strftimeResult == 0) { + log_add (log_Fatal, "strftime() failed: %s.", strerror (errno)); + abort (); + } + + // The user needs to create the debug/ dir manually. If there + // is no debug/ dir, no log will be created. + conn->debugFile = uio_fopen (configDir, dumpFileName, "wt"); + if (conn->debugFile == NULL) { + log_add (log_Debug, "Not creating a netplay debug log for " + "player %d.", player); + } else { + log_add (log_Debug, "Creating netplay debug log '%s' for " + "player %d.", dumpFileName, player); + if (netplayDebugFile == NULL) { + // Debug info relating to no specific network connection + // is sent to the first opened one. + netplayDebugFile = conn->debugFile; + } + } + } +#endif + conn->nd = NULL; conn->player = player; conn->state = NetState_unconnected; @@ -129,6 +183,19 @@ NetConnection_delete(NetConnection *conn) { } free(conn->readBuf); PacketQueue_uninit(&conn->queue); + +#ifdef NETPLAY_DEBUG_FILE + if (conn->debugFile != NULL) { + if (netplayDebugFile == conn->debugFile) { + // There may be other network connections, with an open + // debug file, but we don't know about that. + // The debugging person just has to work around that. + netplayDebugFile = NULL; + } + uio_fclose(conn->debugFile); + } +#endif + free(conn); } @@ -317,4 +384,3 @@ NetConnection_getStatistics(NetConnection *conn) { } #endif - diff --git a/sc2/src/sc2code/netplay/netconnection.h b/sc2/src/sc2code/netplay/netconnection.h index 8bae636ba..9babd13d1 100644 --- a/sc2/src/sc2code/netplay/netconnection.h +++ b/sc2/src/sc2code/netplay/netconnection.h @@ -43,6 +43,12 @@ typedef void (*NetConnection_ResetCallback)(NetConnection *conn, void *arg); #ifdef NETPLAY_CHECKSUM # include "checkbuf.h" #endif +#if defined(NETPLAY_STATISTICS) || defined(NETCONNECTION_INTERNAL) +# include "packet.h" +#endif +#if defined(NETPLAY_DEBUG) && defined(NETPLAY_DEBUG_FILE) +# include "libs/uio.h" +#endif struct NetConnectionError { NetState state; @@ -54,8 +60,6 @@ struct NetConnectionError { }; #ifdef NETPLAY_STATISTICS -#include "packet.h" - struct NetStatistics { size_t packetsReceived; size_t packetTypeReceived[PACKET_NUM]; @@ -64,6 +68,7 @@ struct NetStatistics { }; #endif + #ifdef NETCONNECTION_INTERNAL #include "libs/net.h" #include "packetq.h" @@ -158,6 +163,10 @@ struct NetConnection { #ifdef NETPLAY_CHECKSUM ChecksumBuffer checksumBuffer; #endif +#if defined(NETPLAY_DEBUG) && defined(NETPLAY_DEBUG_FILE) + uio_Stream *debugFile; +#endif + NetConnection_ConnectCallback connectCallback; NetConnection_CloseCallback closeCallback; // Called when the NetConnection becomes disconnected. @@ -229,6 +238,11 @@ NetConnection_ResetCallback NetConnection_getResetCallback( void *NetConnection_getResetCallbackArg(const NetConnection *conn); +#if defined(NETPLAY_DEBUG) && defined(NETPLAY_DEBUG_FILE) +extern uio_Stream *netplayDebugFile; +#endif + + #endif /* _NETCONNECTION_H */ diff --git a/sc2/src/sc2code/netplay/netplay.h b/sc2/src/sc2code/netplay/netplay.h index 48cc0e8ec..d13bad05f 100644 --- a/sc2/src/sc2code/netplay/netplay.h +++ b/sc2/src/sc2code/netplay/netplay.h @@ -33,6 +33,9 @@ #define NETPLAY_DEBUG /* Extra debugging for netplay */ +//#define NETPLAY_DEBUG_FILE + /* Dump extra debugging information to file. + * Implies NETPLAY_DEBUG.*/ #define NETPLAY_STATISTICS /* Keep some statistics */ #define NETPLAY_CHECKSUM @@ -56,5 +59,11 @@ /* Second argument to listen(). */ +#ifdef NETPLAY_DEBUG_FILE +# define NETPLAY_DEBUG +# define DUMP_CRC_OPS +#endif + + #endif /* _NETPLAY_H */