fix so games don't stall after undo

With these changes the test script no longer produces games that don't
finish. I think they are recovering from the problems produced by one
device doing an undo while another is making a move, or other problems
produced by undo being allowed to happen on any device at any time, but
haven't analyzed the games beyond the test script's verifying that they
all finish with a Winner after all tiles are consumed.

xwords4/common/comms.c

@@ -964,7 +964,7 @@ comms_writeToStream( CommsCtxt* comms, XWStreamCtxt* stream,
 static void
 resetBackoff( CommsCtxt* comms )
 {
-    XP_LOGF( "%s: resetting backoff", __func__ );
+    XP_LOGFF( "%s", "resetting backoff" );
     comms->resendBackoff = 0;
     comms->nextResend = 0;
 }

xwords4/common/engine.c

@@ -22,6 +22,7 @@
 #include "engine.h"
 #include "dictnry.h"
 #include "util.h"
+#include "dbgutil.h"
 
 #ifdef CPLUS
 extern "C" {
@@ -416,7 +417,8 @@ engine_findMove( EngineCtxt* engine, const ModelCtxt* model,
                 engine->nTilesMaxUser = nTilesMax;
             } else {
                 *canMoveP = XP_FALSE;                
-                return XP_TRUE;
+                result = XP_TRUE;
+                goto exit;
             }
         }
 
@@ -557,12 +559,16 @@ engine_findMove( EngineCtxt* engine, const ModelCtxt* model,
         engine_reset( engine ); 
         if ( !isRetry ) {
             isRetry = XP_TRUE;
-            XP_LOGF( "%s: no moves found so retrying", __func__ );
+            XP_LOGFF( "%s", "no moves found so retrying" );
             goto retry;
         }
     }
 
     *canMoveP = canMove;
+#ifdef XWFEATURE_SEARCHLIMIT
+ exit:
+#endif
+    LOG_RETURNF( "%s", boolToStr(result) );
     return result;
 } /* engine_findMove */
 
@@ -1147,7 +1153,7 @@ considerScoreWordHasBlanks( EngineCtxt* engine, XP_U16 blanksLeft,
         } else {
 #ifdef XWFEATURE_BONUSALL
             if ( 0 != engine->allTilesBonus && 0 == engine->nTilesMax ) {
-                XP_LOGF( "%s: adding bonus: %d becoming %d", __func__, score ,
+                XP_LOGFF( "adding bonus: %d becoming %d", score,
                          score + engine->allTilesBonus );
                 score += engine->allTilesBonus;
             }

xwords4/common/server.c

@@ -1338,7 +1338,7 @@ makeRobotMove( ServerCtxt* server )
         XWStreamCtxt* stream = NULL;
 
         XP_Bool trade = forceTrade || 
-            ((newMove.nTiles == 0) && canMove &&
+            ((newMove.nTiles == 0) && !canMove &&
              (server_countTilesInPool( server ) >= MAX_TRAY_TILES));
 
         server->vol.showPrevMove = XP_TRUE;
@@ -1349,7 +1349,7 @@ makeRobotMove( ServerCtxt* server )
         /* trade if unable to find a move */
         if ( trade ) {
             TrayTileSet oldTiles = *model_getPlayerTiles( model, turn );
-            XP_LOGF( "%s: robot trading %d tiles", __func__, oldTiles.nTiles );
+            XP_LOGFF( "robot trading %d tiles", oldTiles.nTiles );
             result = server_commitTrade( server, &oldTiles, NULL );
 
             /* Quick hack to fix gremlin bug where all-robot game seen none
@@ -2515,8 +2515,12 @@ nextTurn( ServerCtxt* server, XP_S16 nxtTurn )
     XP_Bool moreToDo = XP_FALSE;
 
     if ( nxtTurn == PICK_NEXT ) {
-        XP_ASSERT( server->nv.gameState == XWSTATE_INTURN ); /* fired.... */
+        if ( server->nv.gameState != XWSTATE_INTURN ) {
-        if ( currentTurn >= 0 ) {
+            XP_LOGFF( "doing nothing; state %s != XWSTATE_INTURN",
+                      getStateStr(server->nv.gameState) );
+            XP_ASSERT( !moreToDo );
+            goto exit;
+        } else if ( currentTurn >= 0 ) {
             playerTilesLeft = tileCountsOk( server );
             if ( inDuplicateMode(server) ) {
                 nxtTurn = dupe_nextTurn( server );
@@ -2572,6 +2576,7 @@ nextTurn( ServerCtxt* server, XP_S16 nxtTurn )
         moreToDo = XP_TRUE;
     }
 
+ exit:
     if ( moreToDo ) {
         util_requestTime( server->vol.util );
     }
@@ -2956,8 +2961,6 @@ reflectMove( ServerCtxt* server, XWStreamCtxt* stream )
         }
     } else if ( badStack ) {
         moveOk = XP_TRUE;
-    } else {
-        XP_LOGFF( "dropping move: state=%s", getStateStr(server->nv.gameState ) );
     }
     return moveOk;
 } /* reflectMove */
@@ -3948,7 +3951,8 @@ reflectUndos( ServerCtxt* server, XWStreamCtxt* stream, XW_Proto code )
         util_informUndo( server->vol.util );
         nextTurn( server, turn );
     } else {
-        XP_ASSERT(0);
+        XP_LOGFF( "unable to pop to hash %X; dropping", newHash );
+        // XP_ASSERT(0);
         success = XP_TRUE;      /* Otherwise we'll stall */
     }
 
@@ -4058,7 +4062,7 @@ server_receiveMessage( ServerCtxt* server, XWStreamCtxt* incoming )
     XP_Bool accepted = XP_FALSE;
     XP_Bool isServer = amServer( server );
     const XW_Proto code = readProto( server, incoming );
-    XP_LOGF( "%s(code=%s)", __func__, codeToStr(code) );
+    XP_LOGFF( "(code=%s)", codeToStr(code) );
 
     switch ( code ) {
     case XWPROTO_DEVICE_REGISTRATION:
@@ -4089,7 +4093,8 @@ server_receiveMessage( ServerCtxt* server, XWStreamCtxt* incoming )
         if ( XWSTATE_INTURN == server->nv.gameState ) {
             accepted = reflectMoveAndInform( server, incoming );
         } else {
-            XP_LOGFF( "bad state: %s", getStateStr( server->nv.gameState ) );
+            XP_LOGFF( "bad state: %s; dropping", getStateStr( server->nv.gameState ) );
+            accepted = XP_TRUE;
         }
         break;
 
@@ -4102,6 +4107,9 @@ server_receiveMessage( ServerCtxt* server, XWStreamCtxt* incoming )
         }
         if ( accepted ) {
             nextTurn( server, PICK_NEXT );
+        } else {
+            accepted = XP_TRUE; /* don't stall.... */
+            XP_LOGFF( "dropping move: state=%s", getStateStr(server->nv.gameState ) );
         }
         break;