diff --git a/xwords4/common/comms.c b/xwords4/common/comms.c index 9a1cc3a3b..c4e2fd810 100644 --- a/xwords4/common/comms.c +++ b/xwords4/common/comms.c @@ -2427,15 +2427,14 @@ comms_msgProcessed( CommsCtxt* comms, CommsMsgState* state, XP_Bool rejected ) removeAddrRec( comms, state->rec ); } #ifdef LOG_COMMS_MSGNOS - XP_LOGF( "%s(): msg rejected; NOT upping lastMsgRcd to %d", __func__, - state->msgID ); + XP_LOGFF( "msg rejected; NOT upping lastMsgRcd to %d", state->msgID ); #endif } else { AddressRecord* rec = getRecordFor( comms, NULL, state->channelNo, XP_TRUE ); XP_ASSERT( !!rec ); if ( !!rec && rec->lastMsgRcd < state->msgID ) { #ifdef LOG_COMMS_MSGNOS - XP_LOGF( "%s(): upping lastMsgRcd from %d to %d", __func__, rec->lastMsgRcd, state->msgID ); + XP_LOGFF( "upping lastMsgRcd from %d to %d", rec->lastMsgRcd, state->msgID ); #endif rec->lastMsgRcd = state->msgID; } diff --git a/xwords4/common/memstream.c b/xwords4/common/memstream.c index 66071b1ed..52c8c38b2 100644 --- a/xwords4/common/memstream.c +++ b/xwords4/common/memstream.c @@ -403,14 +403,11 @@ mem_stream_getHash( const XWStreamCtxt* p_sctx, XWStreamPos pos ) --len; } - LOG_HEX( ptr, len, __func__ ); - hash = augmentHash( 0, ptr, len ); if ( 0 != bits ) { XP_U8 byt = ptr[len]; byt &= ~(0xFF << bits); hash = augmentHash( hash, &byt, 1 ); - LOG_HEX( &byt, 1, __func__ ); } hash = finishHash( hash ); diff --git a/xwords4/common/model.c b/xwords4/common/model.c index 6fbea0cfa..554b54768 100644 --- a/xwords4/common/model.c +++ b/xwords4/common/model.c @@ -328,12 +328,14 @@ model_hashMatches( const ModelCtxt* model, const XP_U32 hash ) { StackCtxt* stack = model->vol.stack; XP_Bool matches = hash == stack_getHash( stack ); + XP_LOGFF( "(hash=%X) => %d", hash, matches ); return matches; } XP_Bool model_popToHash( ModelCtxt* model, const XP_U32 hash, PoolContext* pool ) { + LOG_FUNC(); XP_U16 nPopped = 0; StackCtxt* stack = model->vol.stack; const XP_U16 nEntries = stack_getNEntries( stack ); @@ -341,12 +343,16 @@ model_popToHash( ModelCtxt* model, const XP_U32 hash, PoolContext* pool ) XP_S16 foundAt = -1; for ( XP_U16 ii = 0; ii < nEntries; ++ii ) { - if ( hash == stack_getHash( stack ) ) { + XP_U32 hash1 = stack_getHash( stack ); + XP_LOGFF( "#%d: comparing %X with %X", nEntries-ii-1, hash, hash1 ); + if ( hash == hash1 ) { foundAt = ii; break; } if ( ! stack_popEntry( stack, &entries[ii] ) ) { + XP_LOGFF( "stack_popEntry(%d) failed", ii ); + XP_ASSERT(0); break; } ++nPopped; @@ -359,24 +365,22 @@ model_popToHash( ModelCtxt* model, const XP_U32 hash, PoolContext* pool ) XP_Bool found = -1 != foundAt; if ( found ) { - XP_LOGF( "%s: undoing %d turns to match hash %X", __func__, - foundAt, hash ); + if ( 0 < foundAt ) { /* if 0, nothing to do */ + XP_LOGF( "%s: undoing %d turns to match hash %X", __func__, + foundAt, hash ); #ifdef DEBUG - XP_Bool success = + XP_Bool success = #endif - model_undoLatestMoves( model, pool, foundAt, NULL, NULL ); - XP_ASSERT( success ); + model_undoLatestMoves( model, pool, foundAt, NULL, NULL ); + XP_ASSERT( success ); + } /* Assert not needed for long */ XP_ASSERT( hash == stack_getHash( model->vol.stack ) ); } else { XP_ASSERT( nEntries == stack_getNEntries(stack) ); } -#ifdef DEBUG_HASHING - XP_LOGF( "%s(%X) => %s (nEntries=%d)", __func__, hash, boolToStr(found), - nEntries ); -#endif - + LOG_RETURNF( "%s (hash=%X, nEntries=%d)", boolToStr(found), hash, nEntries ); return found; } /* model_popToHash */ @@ -933,6 +937,7 @@ XP_Bool model_undoLatestMoves( ModelCtxt* model, PoolContext* pool, XP_U16 nMovesSought, XP_U16* turnP, XP_S16* moveNumP ) { + XP_ASSERT( 0 < nMovesSought ); /* this case isn't handled correctly */ StackCtxt* stack = model->vol.stack; XP_Bool success; XP_S16 moveSought = !!moveNumP ? *moveNumP : -1; diff --git a/xwords4/common/movestak.c b/xwords4/common/movestak.c index 299e341a3..f0e67b7dd 100644 --- a/xwords4/common/movestak.c +++ b/xwords4/common/movestak.c @@ -261,9 +261,6 @@ pushEntryImpl( StackCtxt* stack, const StackEntry* entry ) ++stack->nEntries; stack->highWaterMark = stack->nEntries; stack->top = stream_setPos( stream, POS_WRITE, oldLoc ); -#ifdef DEBUG_HASHING - XP_LOGSTREAM( stack->data ); -#endif SET_DIRTY( stack ); } /* pushEntryImpl */ @@ -515,9 +512,6 @@ stack_popEntry( StackCtxt* stack, StackEntry* entry ) setCacheReadyFor( stack, nn ); /* set cachedPos by side-effect */ stack->top = stack->cachedPos; } -#ifdef DEBUG_HASHING - XP_LOGSTREAM( stack->data ); -#endif return found; } /* stack_popEntry */ diff --git a/xwords4/common/server.c b/xwords4/common/server.c index 1517a3ae6..270be0a67 100644 --- a/xwords4/common/server.c +++ b/xwords4/common/server.c @@ -1281,6 +1281,7 @@ mkServerStream( ServerCtxt* server ) static XP_Bool makeRobotMove( ServerCtxt* server ) { + LOG_FUNC(); XP_Bool result = XP_FALSE; XP_Bool searchComplete; XP_S16 turn; @@ -1397,6 +1398,7 @@ makeRobotMove( ServerCtxt* server ) XP_ASSERT( gi->players[turn].secondsUsed == 0 ); } + LOG_RETURNF( "%s", boolToStr(result) ); return result; /* always return TRUE after robot move? */ } /* makeRobotMove */ @@ -1563,7 +1565,7 @@ server_do( ServerCtxt* server ) } else { XP_Bool moreToDo = XP_FALSE; server->serverDoing = XP_TRUE; - XP_LOGF( "%s(): gameState: %s", __func__, getStateStr(server->nv.gameState) ); + XP_LOGFF( "gameState: %s", getStateStr(server->nv.gameState) ); switch( server->nv.gameState ) { case XWSTATE_BEGIN: if ( server->nv.pendingRegistrations == 0 ) { /* all players on @@ -2506,7 +2508,7 @@ getPlayerTime( ServerCtxt* server, XWStreamCtxt* stream, XP_U16 turn ) static void nextTurn( ServerCtxt* server, XP_S16 nxtTurn ) { - LOG_FUNC(); + XP_LOGFF( "(nxtTurn=%d)", nxtTurn ); CurGameInfo* gi = server->vol.gi; XP_Bool playerTilesLeft = XP_FALSE; XP_S16 currentTurn = server->nv.currentTurn; @@ -2529,6 +2531,7 @@ nextTurn( ServerCtxt* server, XP_S16 nxtTurn ) previous turn was or how many tiles he had: it's a sure thing he "has" enough to be allowed to take the turn just undone. */ playerTilesLeft = XP_TRUE; + XP_ASSERT( nxtTurn == model_getNextTurn( server->vol.model ) ); } SETSTATE( server, XWSTATE_INTURN ); /* even if game over, if undoing */ @@ -2543,8 +2546,7 @@ nextTurn( ServerCtxt* server, XP_S16 nxtTurn ) SETSTATE( server, XWSTATE_NEEDSEND_ENDGAME ); /* this is it */ moreToDo = XP_TRUE; } else if ( currentTurn >= 0 ) { - XP_LOGF( "%s: Doing nothing; waiting for server to end game", - __func__ ); + XP_LOGFF( "%s", "Doing nothing; waiting for server to end game" ); setTurn( server, -1 ); /* I'm the client. Do ++nothing++. */ } @@ -2700,7 +2702,7 @@ static XP_Bool readMoveInfo( ServerCtxt* server, XWStreamCtxt* stream, XP_U16* whoMovedP, XP_Bool* isTradeP, TrayTileSet* newTiles, TrayTileSet* tradedTiles, - XP_Bool* legalP ) + XP_Bool* legalP, XP_Bool* badStackP ) { LOG_FUNC(); XP_Bool success = XP_TRUE; @@ -2714,7 +2716,8 @@ readMoveInfo( ServerCtxt* server, XWStreamCtxt* stream, || model_popToHash( server->vol.model, hashReceived, server->pool ); if ( !success ) { - XP_LOGF( "%s: hash mismatch: %X not found",__func__, hashReceived ); + XP_LOGFF( "hash mismatch: %X not found", hashReceived ); + *badStackP = XP_TRUE; #ifdef DEBUG_HASHING } else { XP_LOGF( "%s: hash match: %X",__func__, hashReceived ); @@ -2750,6 +2753,7 @@ readMoveInfo( ServerCtxt* server, XWStreamCtxt* stream, } } } + LOG_RETURNF( "%s", boolToStr(success) ); return success; } /* readMoveInfo */ @@ -2821,8 +2825,9 @@ reflectMoveAndInform( ServerCtxt* server, XWStreamCtxt* stream ) XP_ASSERT( gi->serverRole == SERVER_ISSERVER ); + XP_Bool badStack = XP_FALSE; success = readMoveInfo( server, stream, &whoMoved, &isTrade, &newTiles, - &tradedTiles, &isLegalMove ); /* modifies model */ + &tradedTiles, &isLegalMove, &badStack ); /* modifies model */ XP_ASSERT( !success || isLegalMove ); /* client should always report as true */ isLegalMove = XP_TRUE; @@ -2891,6 +2896,8 @@ reflectMoveAndInform( ServerCtxt* server, XWStreamCtxt* stream ) if ( doRequest ) { util_requestTime( server->vol.util ); } + } else if ( badStack ) { + success = XP_TRUE; /* so we don't reject the move forever */ } return success; } /* reflectMoveAndInform */ @@ -2898,7 +2905,6 @@ reflectMoveAndInform( ServerCtxt* server, XWStreamCtxt* stream ) static XP_Bool reflectMove( ServerCtxt* server, XWStreamCtxt* stream ) { - XP_Bool moveOk; XP_Bool isTrade; XP_Bool isLegal; XP_U16 whoMoved; @@ -2908,10 +2914,19 @@ reflectMove( ServerCtxt* server, XWStreamCtxt* stream ) XWStreamCtxt* mvStream = NULL; XWStreamCtxt* wordsStream = NULL; - moveOk = XWSTATE_INTURN == server->nv.gameState - && server->nv.currentTurn >= 0 - && readMoveInfo( server, stream, &whoMoved, &isTrade, &newTiles, - &tradedTiles, &isLegal ); /* modifies model */ + XP_Bool badStack = XP_FALSE; + XP_Bool moveOk = XP_FALSE; + + if ( XWSTATE_INTURN != server->nv.gameState ) { + XP_LOGFF( "BAD: game state: %s, not XWSTATE_INTURN", getStateStr(server->nv.gameState ) ); + } else if ( server->nv.currentTurn < 0 ) { + XP_LOGFF( "BAD: currentTurn %d < 0", server->nv.currentTurn ); + } else if ( ! readMoveInfo( server, stream, &whoMoved, &isTrade, &newTiles, + &tradedTiles, &isLegal, &badStack ) ) { /* modifies model */ + XP_LOGFF( "%s", "BAD: readMoveInfo() failed" ); + } else { + moveOk = XP_TRUE; + } if ( moveOk ) { if ( isTrade ) { @@ -2939,9 +2954,10 @@ reflectMove( ServerCtxt* server, XWStreamCtxt* stream ) XP_ASSERT( server->vol.gi->serverRole == SERVER_ISCLIENT ); handleIllegalWord( server, stream ); } + } else if ( badStack ) { + moveOk = XP_TRUE; } else { - XP_LOGF( "%s: dropping move: state=%s", __func__, - getStateStr(server->nv.gameState ) ); + XP_LOGFF( "dropping move: state=%s", getStateStr(server->nv.gameState ) ); } return moveOk; } /* reflectMove */ @@ -3862,7 +3878,7 @@ handleMoveOk( ServerCtxt* server, XWStreamCtxt* XP_UNUSED(incoming) ) static void sendUndoTo( ServerCtxt* server, XP_U16 devIndex, XP_U16 nUndone, - XP_U16 lastUndone ) + XP_U16 lastUndone, XP_U32 newHash ) { XWStreamCtxt* stream; CurGameInfo* gi = server->vol.gi; @@ -3873,19 +3889,20 @@ sendUndoTo( ServerCtxt* server, XP_U16 devIndex, XP_U16 nUndone, stream_putU16( stream, nUndone ); stream_putU16( stream, lastUndone ); + stream_putU32( stream, newHash ); stream_destroy( stream ); } /* sendUndoTo */ static void -sendUndoToClientsExcept( ServerCtxt* server, XP_U16 skip, - XP_U16 nUndone, XP_U16 lastUndone ) +sendUndoToClientsExcept( ServerCtxt* server, XP_U16 skip, XP_U16 nUndone, + XP_U16 lastUndone, XP_U32 newHash ) { XP_U16 devIndex; for ( devIndex = 1; devIndex < server->nv.nDevices; ++devIndex ) { if ( devIndex != skip ) { - sendUndoTo( server, devIndex, nUndone, lastUndone ); + sendUndoTo( server, devIndex, nUndone, lastUndone, newHash ); } } } /* sendUndoToClientsExcept */ @@ -3893,6 +3910,7 @@ sendUndoToClientsExcept( ServerCtxt* server, XP_U16 skip, static XP_Bool reflectUndos( ServerCtxt* server, XWStreamCtxt* stream, XW_Proto code ) { + LOG_FUNC(); XP_U16 nUndone; XP_S16 lastUndone; XP_U16 turn; @@ -3901,23 +3919,40 @@ reflectUndos( ServerCtxt* server, XWStreamCtxt* stream, XW_Proto code ) nUndone = stream_getU16( stream ); lastUndone = stream_getU16( stream ); + XP_U32 newHash = 0; + if ( 0 < stream_getSize( stream ) ) { + newHash = stream_getU32( stream ); + } + XP_ASSERT( 0 == stream_getSize( stream ) ); + + if ( 0 == newHash ) { + success = model_undoLatestMoves( model, server->pool, nUndone, &turn, + &lastUndone ); + XP_ASSERT( turn == model_getNextTurn( model ) ); + } else { + success = model_popToHash( model, newHash, server->pool ); + turn = model_getNextTurn( model ); + } - success = model_undoLatestMoves( model, server->pool, nUndone, &turn, - &lastUndone ); if ( success ) { + XP_LOGFF( "popped down to %X", model_getHash( model ) ); sortTilesIf( server, turn ); if ( code == XWPROTO_UNDO_INFO_CLIENT ) { /* need to inform */ XP_U16 sourceClientIndex = getIndexForStream( server, stream ); sendUndoToClientsExcept( server, sourceClientIndex, nUndone, - lastUndone ); + lastUndone, newHash ); } util_informUndo( server->vol.util ); nextTurn( server, turn ); + } else { + XP_ASSERT(0); + success = XP_TRUE; /* Otherwise we'll stall */ } + LOG_RETURNF( "%s", boolToStr(success) ); return success; } /* reflectUndos */ #endif @@ -3925,6 +3960,7 @@ reflectUndos( ServerCtxt* server, XWStreamCtxt* stream, XW_Proto code ) XP_Bool server_handleUndo( ServerCtxt* server, XP_U16 limit ) { + LOG_FUNC(); XP_Bool result = XP_FALSE; XP_U16 lastTurnUndone = 0; /* quiet compiler good */ XP_U16 nUndone = 0; @@ -3958,13 +3994,15 @@ server_handleUndo( ServerCtxt* server, XP_U16 limit ) result = nUndone > 0 ; if ( result ) { + XP_U32 newHash = model_getHash( model ); #ifndef XWFEATURE_STANDALONE_ONLY XP_ASSERT( lastUndone != 0xFFFF ); + XP_LOGFF( "popped to hash %X", newHash ); if ( server->vol.gi->serverRole == SERVER_ISCLIENT ) { - sendUndoTo( server, SERVER_DEVICE, nUndone, lastUndone ); + sendUndoTo( server, SERVER_DEVICE, nUndone, lastUndone, newHash ); } else { sendUndoToClientsExcept( server, SERVER_DEVICE, nUndone, - lastUndone ); + lastUndone, newHash ); } #endif sortTilesIf( server, lastTurnUndone ); @@ -3975,6 +4013,7 @@ server_handleUndo( ServerCtxt* server, XP_U16 limit ) util_userError( server->vol.util, ERR_CANT_UNDO_TILEASSIGN ); } + LOG_RETURNF( "%s", boolToStr(result) ); return result; } /* server_handleUndo */ @@ -4110,7 +4149,8 @@ server_receiveMessage( ServerCtxt* server, XWStreamCtxt* incoming ) XP_ASSERT( isServer == amServer( server ) ); /* caching value is ok? */ stream_close( incoming ); - XP_LOGF( "%s() => %d (code=%s)", __func__, accepted, codeToStr(code) ); + XP_LOGFF( "=> %d (code=%s)", accepted, codeToStr(code) ); + // XP_ASSERT( accepted ); /* do not commit!!! */ return accepted; } /* server_receiveMessage */ #endif diff --git a/xwords4/common/strutils.c b/xwords4/common/strutils.c index 66e465f86..ba7b5c986 100644 --- a/xwords4/common/strutils.c +++ b/xwords4/common/strutils.c @@ -371,9 +371,6 @@ augmentHash( XP_U32 hash, const XP_U8* ptr, XP_U16 len ) hash += (hash << 10); hash ^= (hash >> 6); } -#ifdef DEBUG_HASHING - XP_LOGF( "%s: hashed %d bytes -> %X", __func__, len, (unsigned int)hash ); -#endif return hash; } diff --git a/xwords4/linux/linuxmain.c b/xwords4/linux/linuxmain.c index d3843c179..b5cf28b75 100644 --- a/xwords4/linux/linuxmain.c +++ b/xwords4/linux/linuxmain.c @@ -771,7 +771,7 @@ secondTimerFired( gpointer data ) XP_U16 undoRatio = cGlobals->params->undoRatio; if ( 0 != undoRatio ) { if ( (XP_RANDOM() % 1000) < undoRatio ) { - XP_LOGF( "%s: calling server_handleUndo", __func__ ); + XP_LOGFF( "%s", "calling server_handleUndo()" ); if ( server_handleUndo( game->server, 1 ) ) { board_draw( game->board ); } diff --git a/xwords4/linux/linuxsms.c b/xwords4/linux/linuxsms.c index 6053305a5..368a3fb11 100644 --- a/xwords4/linux/linuxsms.c +++ b/xwords4/linux/linuxsms.c @@ -195,7 +195,9 @@ decodeAndDelete( LinSMSData* storage, const gchar* name, char phone[32]; int port; int matched = sscanf( contents, ADDR_FMT, phone, &port ); - if ( 2 == matched ) { + if ( 2 != matched ) { + XP_LOGFF( "ERROR: found %d matches instead of 2", matched ); + } else { gchar* eol = strstr( contents, "\n" ); *eol = '\0'; XP_ASSERT( !*eol ); @@ -216,8 +218,6 @@ decodeAndDelete( LinSMSData* storage, const gchar* name, XP_LOGFF( " message came from phone: %s, port: %d", phone, port ); addr->u.sms.port = port; } - } else { - XP_ASSERT(0); } g_free( contents ); diff --git a/xwords4/linux/scripts/discon_ok2.py b/xwords4/linux/scripts/discon_ok2.py index 3e7448845..86d708797 100755 --- a/xwords4/linux/scripts/discon_ok2.py +++ b/xwords4/linux/scripts/discon_ok2.py @@ -332,7 +332,7 @@ class Device(): else: print('NOT killing') self.proc = None - self.check_game() + self.check_game_over() def handleAllDone(self): global gDeadLaunches @@ -386,7 +386,7 @@ class Device(): elif RNUM < 10: self.devID += 'x' - def check_game(self): + def check_game_over(self): if self.gameOver and not self.allDone: allDone = True for dev in self.peers: @@ -400,31 +400,6 @@ class Device(): assert self.game == dev.game dev.allDone = True - # print('Closing', self.connname, datetime.datetime.now()) - # for dev in Device.sConnnameMap[self.connname]: - # dev.kill() -# # kill_from_logs $OTHERS $KEY -# for ID in $OTHERS $KEY; do -# echo -n "${ID}:${LOGS[$ID]}, " -# kill_from_log ${LOGS[$ID]} || /bin/true -# send_dead $ID -# close_device $ID $DONEDIR "game over" -# done -# echo "" -# # XWRELAY_ERROR_DELETED may be old -# elif grep -aq 'relay_error_curses(XWRELAY_ERROR_DELETED)' $LOG; then -# echo "deleting $LOG $(connName $LOG) b/c another resigned" -# kill_from_log $LOG || /bin/true -# close_device $KEY $DEADDIR "other resigned" -# elif grep -aq 'relay_error_curses(XWRELAY_ERROR_DEADGAME)' $LOG; then -# echo "deleting $LOG $(connName $LOG) b/c another resigned" -# kill_from_log $LOG || /bin/true -# close_device $KEY $DEADDIR "other resigned" -# else -# maybe_resign $KEY -# fi -# } - def makeSMSPhoneNo( game, dev ): return '{:03d}{:03d}'.format( game, dev )