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,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

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
 }

sc2/src/sc2code/netplay/checksum.h

@@ -25,6 +25,7 @@
 typedef uint32 Checksum;
 
 
+#include "netplay.h"
 #include "crc.h"
 
 #include "element.h"

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;

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 <stddef.h>
 
-// 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 */
 

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 <assert.h>
 #include <stdlib.h>
+#if defined(NETPLAY_DEBUG) && defined(NETPLAY_DEBUG_FILE)
+#	include <errno.h>
+#	include <time.h>
+#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
 
-

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 */
 
 

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 */