xboard spurious "undo": log file trace

Discussion of chess software programming and technical issues.

Moderators: hgm, Dann Corbit, Harvey Williamson

User avatar
sje
Posts: 4675
Joined: Mon Mar 13, 2006 7:43 pm

xboard spurious "undo": log file trace

Post by sje »

Playing on ICC via xboard, Symbolic encountered a spurious undo directive issued by xboard after an opponent resigned out of turn and after a new game had started.

Code: Select all

2015-10-09 17&#58;21&#58;57.329 < time 57000
2015-10-09 17&#58;21&#58;57.329 < otim 55500
2015-10-09 17&#58;21&#58;57.329 = Program time&#58; 9&#58;30.000
2015-10-09 17&#58;21&#58;57.329 < usermove Re8
2015-10-09 17&#58;21&#58;57.329 = Opponent time&#58; 9&#58;15.000
2015-10-09 17&#58;21&#58;57.329 = Playing&#58; 31... Re8
2015-10-09 17&#58;21&#58;57.330 = FEN&#58; 3kr3/ppn2R2/2p5/3pPB2/3P4/2N1K3/PP6/8 w - - 5 32
2015-10-09 17&#58;21&#58;57.333 = C'tor&#58; TabsSearch
2015-10-09 17&#58;21&#58;57.336 > 1 496 0 2 Rd7+
2015-10-09 17&#58;21&#58;57.336 > 2 496 0 80 Rd7+ Kc8
2015-10-09 17&#58;21&#58;57.337 > 3 496 0 156 Rd7+ Kc8 Rxd5+
2015-10-09 17&#58;21&#58;57.339 > 4 496 0 1661 Rd7+ Kc8 Rxd5+ Kb8
2015-10-09 17&#58;21&#58;57.339 > 5 496 0 1880 Rd7+ Kc8 Rxd5+ Kb8 Rd6
2015-10-09 17&#58;21&#58;57.342 > 6 496 0 5093 Rd7+ Kc8 Rxd5+ Kb8 Rd6 a6
2015-10-09 17&#58;21&#58;57.352 > 7 496 1 13669 Rd7+ Kc8 Rxd5+ Kb8 Rd6 a6 b4
2015-10-09 17&#58;21&#58;57.366 > 8 496 3 32949 Rd7+ Kc8 Rxd5+ Kb8 Rd6 a6 b4 Rg8
2015-10-09 17&#58;22&#58;05.722 > 9 493 838 14867522 Rd7+ Kc8 Rxd5+ Kb8 Rd6 a6 b4 Rf8 Kf4 Rh8 a4 Rh2
2015-10-09 17&#58;22&#58;07.436 < result 1-0 &#123;MR-LEE resigns&#125;
2015-10-09 17&#58;22&#58;07.437 < force
2015-10-09 17&#58;22&#58;07.437 < ping 4
2015-10-09 17&#58;22&#58;07.449 < new
2015-10-09 17&#58;22&#58;07.449 < random
2015-10-09 17&#58;22&#58;07.449 < ics 207.192.66.15
2015-10-09 17&#58;22&#58;07.449 < post
2015-10-09 17&#58;22&#58;07.449 < hard
2015-10-09 17&#58;22&#58;07.449 < easy
2015-10-09 17&#58;22&#58;07.449 < ping 5
2015-10-09 17&#58;22&#58;10.950 < level 0 15 0
2015-10-09 17&#58;22&#58;10.950 < name MR-LEE
2015-10-09 17&#58;22&#58;10.950 < rating 2286 1919
2015-10-09 17&#58;22&#58;11.598 = D'tor&#58; TabsSearch
2015-10-09 17&#58;22&#58;11.599 = &#91;+4.936/9/8.388/14,867,522&#93; 32. Rd7+ Kc8 33. Rxd5+ Kb8 34. Rd6 a6 35. b4 Rf8 36. Kf4 Rh8 37. a4 Rh2
2015-10-09 17&#58;22&#58;11.599 = Playing&#58; 32. Rd7+
2015-10-09 17&#58;22&#58;11.599 = FEN&#58; 3kr3/ppnR4/2p5/3pPB2/3P4/2N1K3/PP6/8 b - - 6 32
2015-10-09 17&#58;22&#58;11.599 > tellothers &#91;+4.936/9/8.388/14,867,522&#93; 32. Rd7+ Kc8 33. Rxd5+ Kb8 34. Rd6 a6 35. b4 Rf8 36. Kf4 Rh8 37. a4 Rh2
2015-10-09 17&#58;22&#58;11.599 = Forced mode is enabled.
2015-10-09 17&#58;22&#58;11.599 > move Rd7+
2015-10-09 17&#58;22&#58;11.599 = New game
2015-10-09 17&#58;22&#58;11.599 < undo
2015-10-09 17&#58;22&#58;11.599 > pong 4
2015-10-09 17&#58;22&#58;11.599 = FEN&#58; rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq - 0 1
2015-10-09 17&#58;22&#58;11.599 = Forced mode is disabled.
2015-10-09 17&#58;22&#58;11.600 = Pondering is disabled.
2015-10-09 17&#58;22&#58;11.600 = Posting is disabled.
2015-10-09 17&#58;22&#58;11.600 = Randomization is disabled.
2015-10-09 17&#58;22&#58;11.600 = Randomization is enabled.
2015-10-09 17&#58;22&#58;11.600 = ICS&#58; 207.192.66.15
2015-10-09 17&#58;22&#58;11.600 = Posting is enabled.
2015-10-09 17&#58;22&#58;11.600 = Pondering is enabled.
2015-10-09 17&#58;22&#58;11.600 = Pondering is disabled.
2015-10-09 17&#58;22&#58;11.600 = Opponent name&#58; MR-LEE
2015-10-09 17&#58;22&#58;11.600 > pong 5
2015-10-09 17&#58;22&#58;11.600 = Ratings&#58; 2286/1919
2015-10-09 17&#58;22&#58;11.600 > Level set to&#58; 0 15 0
2015-10-09 17&#58;22&#58;11.600 > tellopponent Hello MR-LEE, I hope you enjoy the game.
2015-10-09 17&#58;22&#58;11.600 > Error &#40;insufficient history&#41;&#58; undo
2015-10-09 17&#58;22&#58;14.020 < time 90000
2015-10-09 17&#58;22&#58;14.020 < otim 90000
2015-10-09 17&#58;22&#58;14.021 = Program time&#58; 15&#58;00.000
2015-10-09 17&#58;22&#58;14.021 < usermove c4
Top
User avatar
hgm
Posts: 27701
Joined: Fri Mar 10, 2006 10:06 am
Location: Amsterdam
Full name: H G Muller

Re: xboard spurious "undo": log file trace

Post by hgm »

Well, that is not spurious, is it? Symbolic plays Rd7+, and XBoard undoes it.

[Edit] Sorry, I guess it is. Symbolic had not answered to ping 4 yet, so I guess that XBoard should have realized that the move belongs to the previous game, and is not sent after 'new' was received. So it should just have ignored it.

I will have a look at the code that is responsible for this. It could be that code for engines without ping is activated here even when the engine does support ping.
Last edited by hgm on Fri Oct 09, 2015 10:12 pm, edited 1 time in total.
Top
User avatar
hgm
Posts: 27701
Joined: Fri Mar 10, 2006 10:06 am
Location: Amsterdam
Full name: H G Muller

Re: xboard spurious "undo": log file trace

Post by hgm »

Near the top of HandleMachineMove() I find this:

Code: Select all

        /* This method is only useful on engines that support ping */
        if &#40;cps->lastPing != cps->lastPong&#41; &#123;
	  if &#40;gameMode == BeginningOfGame&#41; &#123;
	    /* Extra move from before last new; ignore */
	    if &#40;appData.debugMode&#41; &#123;
		fprintf&#40;debugFP, "Ignoring extra move from %s\n", cps->which&#41;;
	    &#125;
	  &#125; else &#123;
	    if &#40;appData.debugMode&#41; &#123;
		fprintf&#40;debugFP, "Undoing extra move from %s, gameMode %d\n",
			cps->which, gameMode&#41;;
	    &#125;

            SendToProgram&#40;"undo\n", cps&#41;;
	  &#125;
	  return;
	&#125;

	switch &#40;gameMode&#41; &#123;
	  case BeginningOfGame&#58;
	    /* Extra move from before last reset; ignore */
	    if &#40;appData.debugMode&#41; &#123;
		fprintf&#40;debugFP, "Ignoring extra move from %s\n", cps->which&#41;;
	    &#125;
	    return;

	  case EndOfGame&#58;
	  case IcsIdle&#58;
	  default&#58;
	    /* Extra move after we tried to stop.  The mode test is
	       not a reliable way of detecting this problem, but it's
	       the best we can do on engines that don't support ping.
	    */
	    if &#40;appData.debugMode&#41; &#123;
		fprintf&#40;debugFP, "Undoing extra move from %s, gameMode %d\n",
			cps->which, gameMode&#41;;
	    &#125;
	    SendToProgram&#40;"undo\n", cps&#41;;
	    return;

	  case MachinePlaysWhite&#58;
	  case IcsPlayingWhite&#58;
	    machineWhite = TRUE;
	    break;

	  case MachinePlaysBlack&#58;
	  case IcsPlayingBlack&#58;
	    machineWhite = FALSE;
	    break;

	  case TwoMachinesPlay&#58;
	    machineWhite = &#40;cps->twoMachinesColor&#91;0&#93; == 'w');
	    break;
	&#125;
	if &#40;WhiteOnMove&#40;forwardMostMove&#41; != machineWhite&#41; &#123;
	    if &#40;appData.debugMode&#41; &#123;
		fprintf&#40;debugFP,
			"Ignoring move out of turn by %s, gameMode %d"
			", forwardMost %d\n",
			cps->which, gameMode, forwardMostMove&#41;;
	    &#125;
	    return;
	&#125;
I guess the two parts of this whole section should really be inside an

Code: Select all

if&#40;cps->usePing&#41; &#123;
  ...
&#125; else &#123;
  ...
&#125;
construct.
Top
User avatar
sje
Posts: 4675
Joined: Mon Mar 13, 2006 7:43 pm

Out-of-turn actions

Post by sje »

The safe thing for an operator to do at present when running in ICS mode is to set the ICS notakeback option and have the engine ignore all undo directives.

In the above example, one can see that I have Symbolic report the out-of-sync undo with an Error response using the format as described in the xboard documentation. It appears that xboard ignores this response.

----

In the larger sense, one must wonder that the Laws of Chess allow for an out-of-turn resignation, or any out-of-turn action by a player when the opponent's clock is running. Resignations, draw offers, draw claims, and piece adjustments should all be done while the player's clock is running. Out-of-turn actions, including resignations, distract the opponent and so are generally forbidden. Even though a resignation means the end of the game, just having to listen for a possible resignation may detract from the opponent's thought process. I suggest that a player who resigns out-of-turn be handed the loss of the game with the loss being recorded as a loss by rule infraction forfeit instead of by resignation.
Top
User avatar
sje
Posts: 4675
Joined: Mon Mar 13, 2006 7:43 pm

Another instance, this time undoing White's first move

Post by sje »

Another instance, this time undoing White's first move:

Code: Select all

2015-10-21 07&#58;18&#58;13.363 < time 71600
2015-10-21 07&#58;18&#58;13.363 < otim 84300
2015-10-21 07&#58;18&#58;13.364 = Program time&#58; 11&#58;56.000
2015-10-21 07&#58;18&#58;13.364 = Opponent time&#58; 14&#58;03.000
2015-10-21 07&#58;18&#58;13.364 < usermove c4
2015-10-21 07&#58;18&#58;13.364 = Playing&#58; 21. c4
2015-10-21 07&#58;18&#58;13.364 = FEN&#58; 2r2r1k/1p3ppp/p2p4/3Ppbb1/P1P5/1P4P1/1B2RPBP/5RK1 b - - 0 21
2015-10-21 07&#58;18&#58;13.373 > 1 41 0 6 Rfe8
2015-10-21 07&#58;18&#58;13.373 > 2 26 0 88 Rfe8
2015-10-21 07&#58;18&#58;13.373 > 2 183 0 221 Bd3 Rfe1 Bxe2 Rxe2
2015-10-21 07&#58;18&#58;13.374 > 3 183 0 380 Bd3 Rfe1 Bxe2 Rxe2
2015-10-21 07&#58;18&#58;13.376 > 4 183 0 2238 Bd3 Rfe1 Bxe2 Rxe2
2015-10-21 07&#58;18&#58;13.380 > 5 189 1 6843 Bd3 Rfe1 Bxe2 Rxe2 f5
2015-10-21 07&#58;18&#58;13.396 > 6 180 2 36366 Bd3 Rfe1 Bxe2 Rxe2 f5 Bc3
2015-10-21 07&#58;18&#58;13.478 > 7 178 10 158242 Bd3 Rfe1 Bxe2 Rxe2 f5 h4 Bh6
2015-10-21 07&#58;18&#58;13.903 > 8 168 53 949155 Bd3 Rfe1 Bxe2 Rxe2 f5 h4 Bh6 Bc3
2015-10-21 07&#58;18&#58;15.451 > 9 173 208 3173704 Bd3 Rfe1 Bxe2 Rxe2 f5 h4 Bh6 Bc3 Bc1
2015-10-21 07&#58;18&#58;16.371 < result 0-1 &#123;carbide resigns&#125;
2015-10-21 07&#58;18&#58;16.371 < force
2015-10-21 07&#58;18&#58;16.371 < ping 6
2015-10-21 07&#58;18&#58;16.383 < new
2015-10-21 07&#58;18&#58;16.383 < random
2015-10-21 07&#58;18&#58;16.383 < ics 207.192.66.15
2015-10-21 07&#58;18&#58;16.383 < post
2015-10-21 07&#58;18&#58;16.383 < hard
2015-10-21 07&#58;18&#58;16.383 < easy
2015-10-21 07&#58;18&#58;16.383 < ping 7
2015-10-21 07&#58;18&#58;25.138 < level 0 15 0
2015-10-21 07&#58;18&#58;25.138 < name carbide
2015-10-21 07&#58;18&#58;25.138 < rating 2280 1948
2015-10-21 07&#58;18&#58;25.138 < time 90000
2015-10-21 07&#58;18&#58;25.138 < otim 90000
2015-10-21 07&#58;18&#58;25.138 < go
2015-10-21 07&#58;18&#58;25.193 > 10 167 1182 21305513 Bd3 Rfe1 Bxe2 Rxe2 f5 h4 Bh6 Ba3 Rcd8 Bb4
2015-10-21 07&#58;18&#58;31.274 = &#91;+1.670/10/11.825/21,305,513&#93; 21... Bd3 22. Rfe1 Bxe2 23. Rxe2 f5 24. h4 Bh6 25. Ba3 Rcd8 26. Bb4
2015-10-21 07&#58;18&#58;31.274 = Playing&#58; 21... Bd3
2015-10-21 07&#58;18&#58;31.274 = FEN&#58; 2r2r1k/1p3ppp/p2p4/3Pp1b1/P1P5/1P1b2P1/1B2RPBP/5RK1 w - - 1 22
2015-10-21 07&#58;18&#58;31.274 > tellothers &#91;+1.670/10/11.825/21,305,513&#93; 21... Bd3 22. Rfe1 Bxe2 23. Rxe2 f5 24. h4 Bh6 25. Ba3 Rcd8 26. Bb4
2015-10-21 07&#58;18&#58;31.274 > move Bd3
2015-10-21 07&#58;18&#58;31.274 = Forced mode is enabled.
2015-10-21 07&#58;18&#58;31.274 = New game
2015-10-21 07&#58;18&#58;31.274 < undo
2015-10-21 07&#58;18&#58;31.274 > pong 6
2015-10-21 07&#58;18&#58;31.449 = FEN&#58; rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq - 0 1
2015-10-21 07&#58;18&#58;31.449 = Forced mode is disabled.
2015-10-21 07&#58;18&#58;31.449 = Pondering is disabled.
2015-10-21 07&#58;18&#58;31.449 = Posting is disabled.
2015-10-21 07&#58;18&#58;31.449 = Randomization is disabled.
2015-10-21 07&#58;18&#58;31.449 = Randomization is enabled.
2015-10-21 07&#58;18&#58;31.449 = ICS&#58; 207.192.66.15
2015-10-21 07&#58;18&#58;31.449 = Posting is enabled.
2015-10-21 07&#58;18&#58;31.449 = Pondering is enabled.
2015-10-21 07&#58;18&#58;31.449 = Pondering is disabled.
2015-10-21 07&#58;18&#58;31.449 = Opponent name&#58; carbide
2015-10-21 07&#58;18&#58;31.449 > pong 7
2015-10-21 07&#58;18&#58;31.449 = Ratings&#58; 2280/1948
2015-10-21 07&#58;18&#58;31.449 > Level set to&#58; 0 15 0
2015-10-21 07&#58;18&#58;31.449 = Program time&#58; 15&#58;00.000
2015-10-21 07&#58;18&#58;31.449 > tellopponent Hello carbide, I hope you enjoy the game.
2015-10-21 07&#58;18&#58;31.449 = Opponent time&#58; 15&#58;00.000
2015-10-21 07&#58;18&#58;31.449 = Forced mode is disabled.
2015-10-21 07&#58;18&#58;31.449 = Program is now playing as White.
2015-10-21 07&#58;18&#58;31.450 = &#91;Even/1/0.000/0&#93; 1. d4
2015-10-21 07&#58;18&#58;31.450 = Playing&#58; 1. d4
2015-10-21 07&#58;18&#58;31.451 > tellothers &#91;Even/1/0.000/0&#93; 1. d4
2015-10-21 07&#58;18&#58;31.451 = FEN&#58; rnbqkbnr/pppppppp/8/8/3P4/8/PPP1PPPP/RNBQKBNR b KQkq - 0 1
2015-10-21 07&#58;18&#58;31.451 = Unplaying&#58; 1. d4
2015-10-21 07&#58;18&#58;31.451 > move d4
2015-10-21 07&#58;18&#58;31.451 = FEN&#58; rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq - 0 1
2015-10-21 07&#58;18&#58;33.636 < time 90000
2015-10-21 07&#58;18&#58;33.636 < otim 90000
2015-10-21 07&#58;18&#58;33.636 = Program time&#58; 15&#58;00.000
2015-10-21 07&#58;18&#58;33.636 < usermove Nf6
2015-10-21 07&#58;18&#58;33.636 = Opponent time&#58; 15&#58;00.000
2015-10-21 07&#58;18&#58;33.636 > Error &#40;unrecgonized user move&#41;&#58; Nf6
2015-10-21 07&#58;33&#58;33.709 < result 0-1 &#123;Symbolic forfeits on time&#125;
Top
User avatar
hgm
Posts: 27701
Joined: Fri Mar 10, 2006 10:06 am
Location: Amsterdam
Full name: H G Muller

Re: Another instance, this time undoing White's first move

Post by hgm »

I had some time to fix the backlog of XBoard bugs, but when I got to this one I started doubting that the proposed fix (if-then-else around the code quoted above, based on whether the engine supports ping or not) would cure the problem. In the lastPing != lastPong case a distinction is made between the BeginningOfGame case, and other cases. In the latter case XBoard would reply to the move with "undo".

But I don't see why you would ever reply to a move from before a 'ping' with an 'undo'. XBoard only sends ping when a game ends, (after putting the engine in force mode) or when it starts a new game. So moves received from before the last ping must be moves that belong in the previous game, if the engine is not so buggy as to spontaneously respond to a 'new' command with a move. And moves from a previous game can be ignored. It would in any case be too lateto do something about them: the 'result' and 'force' command have already been sent before the first 'ping', so sending an 'undo' would not change the engine's idea of what the game to which the result applies would have been. It just alters the current position before a 'new' command would obliterate it anyway.

So I guess I will have the entire ping asynchronicity case unconditionally ignore the move.
Top
User avatar
sje
Posts: 4675
Joined: Mon Mar 13, 2006 7:43 pm

Re: Another instance, this time undoing White's first move

Post by sje »

Symbolic echoes input to its log as it is received asynchronously regardless of other processing. Commands are processed in the order in which they are received, and processing of each input directive is done without examination of any queued input. xboard must not assume otherwise, and also should not assume that the move selection process is terminated early when a directive is sent. (Possible exception: the move now directive)

xboard should probably not send a ping unless there is a need for one, and it should wait for the corresponding pong before sending any further directives.
Top
User avatar
sje
Posts: 4675
Joined: Mon Mar 13, 2006 7:43 pm

An unanswered question

Post by sje »

An unanswered question is: Why is xboard sending an undo directive is some cases of out-of-turn resignations and not others? Perhaps there is some hard-to-replicate timing condition.
Top
bob
Posts: 20943
Joined: Mon Feb 27, 2006 7:30 pm
Location: Birmingham, AL

Re: Another instance, this time undoing White's first move

Post by bob »

hgm wrote:I had some time to fix the backlog of XBoard bugs, but when I got to this one I started doubting that the proposed fix (if-then-else around the code quoted above, based on whether the engine supports ping or not) would cure the problem. In the lastPing != lastPong case a distinction is made between the BeginningOfGame case, and other cases. In the latter case XBoard would reply to the move with "undo".

But I don't see why you would ever reply to a move from before a 'ping' with an 'undo'. XBoard only sends ping when a game ends, (after putting the engine in force mode) or when it starts a new game. So moves received from before the last ping must be moves that belong in the previous game, if the engine is not so buggy as to spontaneously respond to a 'new' command with a move. And moves from a previous game can be ignored. It would in any case be too lateto do something about them: the 'result' and 'force' command have already been sent before the first 'ping', so sending an 'undo' would not change the engine's idea of what the game to which the result applies would have been. It just alters the current position before a 'new' command would obliterate it anyway.

So I guess I will have the entire ping asynchronicity case unconditionally ignore the move.
The thing that pisses me off in all of this is that in Unix, I can't flush a pipe. So I HAVE to accept whatever crap might be backlogged and deal with it. Which sometimes introduces a race condition that is painful to work around...

Just not a perfect world. Turns out I never trusted my "new" code because of the skill command and such that tampers with things that are hard to restore. So I always use "no reuse" (-xreuse I think it is) which certainly flushes the pipe since it is destroyed and re-created...

I don't find any noticeable delay in doing so, and see absolutely none of these race issues that I know of...
Top
User avatar
hgm
Posts: 27701
Joined: Fri Mar 10, 2006 10:06 am
Location: Amsterdam
Full name: H G Muller

Re: Another instance, this time undoing White's first move

Post by hgm »

Well, XBoard never waited for pongs, and the protocol specs do not require it to. Processing the commands in order of reception, and not looking for input during thinking is a valid implementation, though.

There seem to be some problems requiring an 'undo' reply to a move, when the user is interrupting an ongoing game while the engine is thinking, by selecting 'Edit Game'. This results in a 'force' command being sent to the engine, in order to make it receptive for the moves the user will be adding/replacing. In Edit Game mode the engine must always be kept in sync with the displayed position, so it can check the moves played by the user for legality.

The expected behavior is that when the user hits Edit Game, he will switch to the currently displayed position in this mode. This need not be the latest position in the game, as you can step through a game in progress, without the engine knowing it. So in general the engine will be out of sync, and if you make thi switch when it is not the engine's turn, the latter would be brought in sync by a series of 'undo' commands.

If a move is still to come in because the engine is thinking, however, it would bring the engine out of sync, because it would necessitate an extra 'undo'.

I guess this really should be solved in the EditGameEvent handler, when it determines how many undos should be sent to the first engine, and already precompensate for the move that is yet to come when the event occurs while the first engine is thinking. Trying to postpone it to when you receive that move is probably a design flaw. As I read the specs, the move is obligatory: when receiving 'force' during thinking, the engine must still produce a move.

I guess a problem is that the engine could also decide to resign or claim a draw at that point, though, without moving. So perhaps a better solution is to set some flag indicating 'stoppedDuringThinking' in the EditGameEvent, and on a move or RESULT command from that engine clear that flag again, but undo the move. None of this is dependent on ping, as the EditGameEvent does not cause ping to be sent to the engine.
Top

Return to “Computer Chess Club: Programming and Technical Discussions”