toward fixing stalls when undo used

There are still some stalls turning up when running the test script,
especially with more than two players in a game, but but it'll be
easier to do the final debugging off my pathetic travel-only
chromebook. And things are already much better. :-)
This commit is contained in:
katianderic 2020-03-14 14:47:26 -07:00
parent 901b70a5f2
commit b1f7b13e78
9 changed files with 88 additions and 81 deletions

View file

@ -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;
}

View file

@ -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 );

View file

@ -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;

View file

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

View file

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

View file

@ -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;
}

View file

@ -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 );
}

View file

@ -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 );

View file

@ -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 )