add script to print comms msg exchange details

xwords4/common/comms.c

@@ -1525,8 +1525,8 @@ sendMsg( CommsCtxt* comms, XWEnv xwe, MsgQueueElem* elem, const CommsConnType fi
     CNO_FMT( cbuf, channelNo );
 
 #ifdef COMMS_CHECKSUM
-    XP_LOGF( TAGFMT() "sending message of len %d on %s with sum %s", TAGPRMS,
+    XP_LOGF( TAGFMT() "sending message on %s: id: %d; len: %d; sum: %s", TAGPRMS,
-             elem->len, cbuf, elem->checksum );
+             cbuf, elem->msgID, elem->len, elem->checksum );
 #endif
 
     CommsAddrRec addr;
@@ -2425,15 +2425,14 @@ comms_checkIncomingStream( CommsCtxt* comms, XWEnv xwe, XWStreamCtxt* stream,
             MsgID lastMsgRcd = 0;
 
 #ifdef COMMS_CHECKSUM
-            {
+            state->len = stream_getSize( stream );
-                XP_U16 len = stream_getSize( stream );
+            // stream_getPtr pts at base, but sum excludes relay header
-                // stream_getPtr pts at base, but sum excludes relay header
+            const XP_U8* ptr = initialLen - state->len + stream_getPtr( stream );
-                const XP_U8* ptr = initialLen - len + stream_getPtr( stream );
+            XP_UCHAR* tmpsum = dutil_md5sum( comms->dutil, xwe, ptr, state->len );
-                XP_UCHAR* sum = dutil_md5sum( comms->dutil, xwe, ptr, len );
+            XP_STRCAT( state->sum, tmpsum );
-                XP_LOGF( TAGFMT() "got message of len %d with sum %s",
+            XP_LOGF( TAGFMT() "got message of len %d with sum %s",
-                         TAGPRMS, len, sum );
+                     TAGPRMS, state->len, state->sum );
-                XP_FREE( comms->mpool, sum );
+            XP_FREE( comms->mpool, tmpsum );
-            }
 #endif
             /* reject too-small message */
             messageValid = stream_getSize( stream ) 
@@ -2469,7 +2468,7 @@ comms_checkIncomingStream( CommsCtxt* comms, XWEnv xwe, XWStreamCtxt* stream,
                 }
 
                 if ( messageValid ) {
-                    msgID = stream_getU32( stream );
+                    state->msgID = msgID = stream_getU32( stream );
                     lastMsgRcd = stream_getU32( stream );
                     CNO_FMT( cbuf, channelNo );
                     XP_LOGF( TAGFMT() "rcd on %s: msgID=%d, lastMsgRcd=%d ",
@@ -2501,7 +2500,6 @@ comms_checkIncomingStream( CommsCtxt* comms, XWEnv xwe, XWStreamCtxt* stream,
                     CNO_FMT( cbuf, channelNo );
                     XP_LOGF( TAGFMT() "got %s; msgID=%d; len=%d", TAGPRMS, cbuf, 
                              msgID, payloadSize );
-                    state->msgID = msgID;
                     state->channelNo = channelNo;
                     comms->lastSaveToken = 0; /* lastMsgRcd no longer valid */
                     stream_setAddress( stream, channelNo );
@@ -2517,7 +2515,7 @@ comms_checkIncomingStream( CommsCtxt* comms, XWEnv xwe, XWStreamCtxt* stream,
         noteHBReceived( comms/* , addr */ );
 
     }
-    LOG_RETURNF( "%s", messageValid?"valid":"invalid" );
+    LOG_RETURNF( "%s (len: %d; sum: %s)", boolToStr(messageValid), state->len, state->sum );
     return messageValid;
 } /* comms_checkIncomingStream */
 
@@ -2525,6 +2523,10 @@ void
 comms_msgProcessed( CommsCtxt* comms, XWEnv xwe,
                     CommsMsgState* state, XP_Bool rejected )
 {
+#ifdef COMMS_CHECKSUM
+    XP_LOGFF( "id: %d; len: %d; sum: %s; rejected: %s", state->msgID, state->len, state->sum,
+              boolToStr(rejected) );
+#endif
     XP_ASSERT( comms == state->comms );
     XP_ASSERT( comms->processingMsg );
 
@@ -2647,12 +2649,21 @@ comms_gameJoined( CommsCtxt* comms, XWEnv xwe, const XP_UCHAR* connname, XWHostI
 static void
 sendEmptyMsg( CommsCtxt* comms, XWEnv xwe, AddressRecord* rec )
 {
-    MsgQueueElem* elem = makeElemWithID( comms, xwe,
+    XWStreamCtxt* stream = NULL;
-                                         0 /*rec? rec->lastMsgRcd : 0*/,
+#ifdef DEBUG
-                                         rec, 
+    XP_U16 sumFood = XP_RANDOM();
-                                         rec? rec->channelNo : 0, NULL );
+    stream = mem_stream_make_raw( MPPARM(comms->mpool)
+                                  dutil_getVTManager(comms->dutil));
+    stream_putU16( stream, sumFood );
+#endif
+    MsgQueueElem* elem = makeElemWithID( comms, xwe, 0, // msgID
+                                         rec, rec? rec->channelNo : 0,
+                                         stream );
     (void)sendMsg( comms, xwe, elem, COMMS_CONN_NONE );
     freeElem( comms, elem );
+#ifdef DEBUG
+    stream_destroy( stream, xwe );
+#endif
 } /* sendEmptyMsg */
 #endif
 

xwords4/common/comms.h

@@ -218,9 +218,13 @@ typedef struct _CommsMsgState {
     struct AddressRecord* rec;
     XP_U32 msgID;
     XP_PlayerAddr channelNo;
+    XP_U16 len;
 #ifdef DEBUG
     const CommsCtxt* comms;
 #endif
+#ifdef COMMS_CHECKSUM
+    XP_UCHAR sum[36];
+#endif
 } CommsMsgState;
 
 XP_Bool comms_checkIncomingStream( CommsCtxt* comms, XWEnv xwe,

xwords4/linux/scripts/discon_ok2.py

@@ -159,7 +159,7 @@ def logReaderStub(dev): dev.logReaderMain()
 
 class Device():
     sHasLDevIDMap = {}
-    sConnNamePat = re.compile('.*got_connect_cmd: connName: "([^"]+)".*$')
+    # sConnNamePat = re.compile('.*got_connect_cmd: connName: "([^"]+)".*$')
     sGameOverPat = re.compile('^\[(\#\d|Winner)\] (.*): (\d+)')
     sTilesLeftPoolPat = re.compile('.*pool_r.*Tiles: (\d+) tiles left in pool')
     sTilesLeftTrayPat = re.compile('.*player \d+ now has (\d+) tiles')

xwords4/linux/scripts/msgtrack.py

@@ -0,0 +1,150 @@
+#!/usr/bin/python3
+
+import argparse, re, sys
+from os import path
+from enum import IntEnum
+"""Given 2-4 logs from the same game (likely created by discon_ok2.py),
+track all the messages they send (or don't.)
+
+Let's track by msg (checksum). For each, track when 
+
+"""
+
+
+class Message():
+    def __init__(self, msgID, sum, msgLen):
+        self.msgID = msgID
+        self.sum = sum
+        self.len = msgLen
+        self.sends = []
+        self.receives = []
+        self.sender = None
+        self.receiver = None
+
+    def __repr__(self):
+        str = '{}: '.format(self.key())
+        str += ' {} => {}'.format(self.sender, self.receiver)
+        firstReceipt = self.receives and self.receives[0][0] or None
+        str += ' sent: {}; arrived: {}'.format(self.firstSendTime(), firstReceipt)
+        (nReceives, nDrops) = self.countReceives();
+        str += '; nSents: {}; nReceives: {}; nDrops: {}'.format(len(self.sends), \
+                nReceives, nDrops)
+        str += '; nLost: {}'.format(len(self.sends) - (len(self.receives)))
+        return str
+
+    def addSend(self, sender, ts):
+        if not self.sender:
+            self.sender = sender
+        else:
+            assert(self.sender == sender)
+        self.sends.append(ts)
+
+    def addReceive(self, receiver, ts, dropped):
+        if not self.receiver:
+            self.receiver = receiver
+        else:
+            assert(self.receiver == receiver)
+        self.receives.append((ts, dropped))
+
+    def pruneEarlySends(self):
+        firstReceipt = self.receives and self.receives[0][0] or None
+        if firstReceipt:
+            while 1 < len(self.sends) and self.sends[1] < firstReceipt:
+                # print('{} < {}: removing from {}'.format(self.sends[1], firstReceipt, self.key()))
+                self.sends.pop()
+
+    def firstSendTime(self):
+        return self.sends[0]
+
+    def countReceives(self):
+        nAccepts = nDrops = 0
+        for tup in self.receives:
+            if tup[1]: nDrops += 1
+            else: nAccepts += 1
+        return (nAccepts, nDrops)
+        
+    def key(self):
+        return Message.mkKey(self.msgID, self.sum, self.len)
+    
+    @staticmethod
+    def mkKey(id, sum, len):
+        return '{:02d}:{}.{:03d}'.format(int(id), sum, len)
+
+def errExit(msg):
+    print(msg, file=sys.stderr)
+    sys.exit(-1)
+
+def mkParser():
+    parser = argparse.ArgumentParser()
+    parser.add_argument('--logs', nargs = '*', dest = 'LOGS',
+                        help = 'two or more logfiles to scan')
+    parser.add_argument('--skip-below', dest = 'SKIP_BELOW', default = 16,
+                        help = 'ignore messages this length or below (acks?)')
+    parser.add_argument('--drop-part', dest = 'DROP_PART', default = '_LOG.txt',
+                        help = 'remove this from filename to shorten')
+    
+    return parser
+
+def getMkMessage(msgs, msgID, len, sum):
+    key = Message.mkKey(msgID, sum, len)
+    msg = msgs.get(key)
+    if not msg:
+        msg = Message(msgID, sum, len)
+        msgs[key] = msg
+    return msg
+
+# pull everything relevant out of logfile
+
+# <16330:7fcf30445a80> 07:54:24:953 <> sendMsg(): sending message of len 135 on cno: 674C|1 with sum 8b8b58399159afdcd54a106d3546423f
+# sSendRE = re.compile('<(.*)> (\d\d:\d\d:\d\d:\d\d\d) .*sending message of len (\d+) on cno: (.*) with sum (.*)')
+
+# <18137:7f9b3c16ba80> 08:52:56:750 <> sendMsg(): sending message on cno: C824|1: id: 1; len: 135; sum: e2eb9c89ad6062e1a1d65e9da649957f
+sSendRE = re.compile('<(.*)> (\d\d:\d\d:\d\d:\d\d\d) .*sending message on cno: (.*): id: (\d+); len: (\d+); sum: (.*)')
+
+# <16327:7f54562f4a80> 07:54:25:359 <> comms_checkIncomingStream(): got message of len 135 with sum 8b8b58399159afdcd54a106d3546423f
+# sReceiveRE = re.compile('<(.*)> (\d\d:\d\d:\d\d:\d\d\d) .*got message of len (\d+) with sum (.*)')
+
+# <23256:7fafba33fa80> 11:53:48:976 ../common/comms.c:comms_msgProcessed(): id: 0; len: 14; sum: 56ba9311510efffe43729241fad1a9b6; rejected: true
+sProcessedRE = re.compile('<(.*)> (\d\d:\d\d:\d\d:\d\d\d) .*comms_msgProcessed.*: id: (\d+); len: (\d+); sum: (.+); rejected: (.+)')
+
+def parse(logfile, shortName, msgs, skipLen):
+    print('parse({})'.format(shortName))
+    with open(logfile, 'r') as log:
+        for line in log:
+            line = line.strip()
+
+            match = sSendRE.match(line)
+            if match:
+                msgLen = int(match.group(5))
+                if msgLen > skipLen:
+                    msg = getMkMessage(msgs, match.group(4), msgLen, match.group(6))
+                    msg.addSend(shortName, match.group(2))
+
+            match = sProcessedRE.match(line)
+            if match:
+                msgLen = int(match.group(4))
+                if msgLen > skipLen:
+                    msgID = match.group(3)
+                    msg = getMkMessage(msgs, msgID, msgLen, match.group(5))
+                    rejected = match.group(6)
+                    msg.addReceive(shortName, match.group(2), rejected=='true')
+
+def main():
+    args = mkParser().parse_args()
+
+    msgs = {}
+    for log in args.LOGS:
+        if not path.exists(log): errExit('file {} not found'.format(log))
+        shortName = path.basename(log).replace(args.DROP_PART, '')
+        parse(log, shortName, msgs, args.SKIP_BELOW)
+
+    asArr = [msgs[key] for key in msgs]
+    asArr.sort(key = lambda msg: msg.firstSendTime())
+    for msg in asArr:
+        # msg.pruneEarlySends()
+        print(msg)
+
+
+##############################################################################
+if __name__ == '__main__':
+    main()