From fecbfdddb6d426e99d9429699df527e25caedb47 Mon Sep 17 00:00:00 2001
From: Eric House <eehouse@eehouse.org>
Date: Sun, 8 Apr 2018 20:46:35 -0700
Subject: [PATCH] tweaks to logging for stack hash debugging

---
 xwords4/common/memstream.c |  2 +-
 xwords4/common/model.c     |  6 ++++++
 xwords4/common/server.c    | 11 +++++++----
 3 files changed, 14 insertions(+), 5 deletions(-)

diff --git a/xwords4/common/memstream.c b/xwords4/common/memstream.c
index 43240920a..cfec0b4aa 100644
--- a/xwords4/common/memstream.c
+++ b/xwords4/common/memstream.c
@@ -398,7 +398,7 @@ mem_stream_getHash( const XWStreamCtxt* p_sctx, XWStreamPos pos,
     }
     hash = finishHash( hash );
 
-    LOG_RETURNF( "%X(%d:%d)", hash, len, bits );
+    LOG_RETURNF( "%X (nBytes=%d;nBits=%d)", hash, len, bits );
     return hash;
 } /* mem_stream_getHash */
 
diff --git a/xwords4/common/model.c b/xwords4/common/model.c
index 81cae3622..76f89a292 100644
--- a/xwords4/common/model.c
+++ b/xwords4/common/model.c
@@ -369,8 +369,14 @@ model_popToHash( ModelCtxt* model, const XP_U32 hash, PoolContext* pool )
         /* Assert not needed for long */
         XP_ASSERT( hash == stack_getHash( model->vol.stack, XP_TRUE )
                    || hash == stack_getHash( model->vol.stack, XP_FALSE ) );
+    } else {
+        XP_ASSERT( nEntries == stack_getNEntries(stack) );
     }
 
+#ifdef DEBUG_HASHING
+    XP_LOGF( "%s(%X) => %s (nEntries=%d)", __func__, hash, boolToStr(found),
+             nEntries );
+#endif
     return found;
 }
 
diff --git a/xwords4/common/server.c b/xwords4/common/server.c
index 663bd01b4..95b381f7f 100644
--- a/xwords4/common/server.c
+++ b/xwords4/common/server.c
@@ -2119,7 +2119,7 @@ sendMoveTo( ServerCtxt* server, XP_U16 devIndex, XP_U16 turn,
         XP_ASSERT( version == server->nv.streamVersion );
         XP_U32 hash = model_getHash( server->vol.model );
 #ifdef DEBUG_HASHING
-        XP_LOGF( "%s: adding hash %x", __func__, (unsigned int)hash );
+        XP_LOGF( "%s: adding hash %X", __func__, (unsigned int)hash );
 #endif
         stream_putU32( stream, hash );
     }
@@ -2164,6 +2164,7 @@ readMoveInfo( ServerCtxt* server, XWStreamCtxt* stream,
               TrayTileSet* newTiles, TrayTileSet* tradedTiles, 
               XP_Bool* legalP )
 {
+    LOG_FUNC();
     XP_Bool success = XP_TRUE;
     XP_Bool legalMove = XP_TRUE;
     XP_Bool isTrade;
@@ -2171,15 +2172,17 @@ readMoveInfo( ServerCtxt* server, XWStreamCtxt* stream,
 #ifdef STREAM_VERS_BIGBOARD
     if ( STREAM_VERS_BIGBOARD <= stream_getVersion( stream ) ) {
         XP_U32 hashReceived = stream_getU32( stream );
-        success = model_hashMatches( server->vol.model, hashReceived )
-            || model_popToHash( server->vol.model, hashReceived, server->pool );
-        // XP_ASSERT( success );   /* I need to understand when this can fail */
+        success = model_hashMatches( server->vol.model, hashReceived );
+        if ( !success ) {
+            success = model_popToHash( server->vol.model, hashReceived, server->pool );
+        }
 #ifdef DEBUG_HASHING
         if ( success ) {
             XP_LOGF( "%s: hash match: %X",__func__, hashReceived );
         } else {
             XP_LOGF( "%s: hash mismatch: %X not found",__func__, hashReceived );
         }
+        // XP_ASSERT( success );   /* I need to understand when this can fail */
 #endif
     }
 #endif