xboard: Spurious undo after a new game and first move

Discussion of chess software programming and technical issues.

Moderators: hgm, Rebel, chrisw

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

xboard: Spurious undo after a new game and first move

Post by sje »

xboard: Spurious undo after a new game and first move

I've posted several cases of xboard issuing a spurious undo directive; here is a case where the undo is sent after a new game is started and after the opponent sends his first move. In all, there are fifteen directives sent between the resignation and the undo:

Code: Select all

2015-12-09 14:15:56.228 = FEN: rB6/5k1p/4pPp1/2Pp4/pq1Pb1P1/7P/PP1R4/2K2QR1 b - - 0 29
2015-12-09 14:15:56.228 > move Bxb8
2015-12-09 14&#58;15&#58;57.725 < time 53900
2015-12-09 14&#58;15&#58;57.725 < otim 75100
2015-12-09 14&#58;15&#58;57.726 = Program time&#58; 8&#58;59.000
2015-12-09 14&#58;15&#58;57.726 < usermove Qc4+
2015-12-09 14&#58;15&#58;57.727 = Opponent time&#58; 12&#58;31.000
2015-12-09 14&#58;15&#58;57.727 = Playing&#58; 29... Qc4+
2015-12-09 14&#58;15&#58;57.727 = FEN&#58; rB6/5k1p/4pPp1/2Pp4/p1qPb1P1/7P/PP1R4/2K2QR1 w - - 1 30
2015-12-09 14&#58;15&#58;57.735 > 1 886 0 22 Qxc4 dxc4
2015-12-09 14&#58;15&#58;57.736 > 2 859 0 139 Qxc4 dxc4 Be5
2015-12-09 14&#58;15&#58;57.736 > 3 877 0 596 Qxc4 dxc4 Be5 a3
2015-12-09 14&#58;15&#58;57.738 > 4 806 0 2242 Qxc4 dxc4 Be5 a3 b3 cxb3 axb3
2015-12-09 14&#58;15&#58;57.744 > 5 814 1 9586 Qxc4 dxc4 Be5 a3 Rgd1 axb2+ Kxb2 Kg8
2015-12-09 14&#58;15&#58;57.758 > 6 811 2 28901 Qxc4 dxc4 Be5 a3 Re1 axb2+ Kxb2 Bc6
2015-12-09 14&#58;15&#58;57.806 > 7 810 7 102610 Qxc4 dxc4 Be5 a3 b3 cxb3 axb3 a2
2015-12-09 14&#58;15&#58;57.938 > 8 810 20 311200 Qxc4 dxc4 Be5 a3 b3 cxb3 axb3 a2 Kb2 Kg8
2015-12-09 14&#58;15&#58;58.425 > 9 817 69 1075404 Qxc4 dxc4 Be5 a3 Rg3 axb2+ Rxb2 Kg8 Bf4 Kh8
2015-12-09 14&#58;15&#58;59.451 > 10 814 171 2734419 Qxc4 dxc4 Be5 a3 Rg3 axb2+ Rxb2 Bc6 a3 Rd8 Re3
2015-12-09 14&#58;16&#58;02.989 > 11 823 525 8348925 Qxc4 dxc4 Be5 a3 Rg3 axb2+ Rxb2 Kg8 Rc3 Bd5 Re3 Bh1 a3
2015-12-09 14&#58;16&#58;04.996 < result 1-0 &#123;MR-LEE resigns&#125;
2015-12-09 14&#58;16&#58;04.997 < force
2015-12-09 14&#58;16&#58;04.997 < ping 12
2015-12-09 14&#58;16&#58;05.009 < new
2015-12-09 14&#58;16&#58;05.009 < random
2015-12-09 14&#58;16&#58;05.009 < ics 207.192.66.15
2015-12-09 14&#58;16&#58;05.009 < post
2015-12-09 14&#58;16&#58;05.009 < hard
2015-12-09 14&#58;16&#58;05.009 < easy
2015-12-09 14&#58;16&#58;05.009 < ping 13
2015-12-09 14&#58;16&#58;07.966 < level 0 15 0
2015-12-09 14&#58;16&#58;07.966 < name MR-LEE
2015-12-09 14&#58;16&#58;07.966 < rating 2245 1860
2015-12-09 14&#58;16&#58;10.013 < time 90000
2015-12-09 14&#58;16&#58;10.013 < otim 90000
2015-12-09 14&#58;16&#58;10.013 < usermove c4
2015-12-09 14&#58;16&#58;11.208 = &#91;+8.230/11/5.257/8,348,925&#93; 30. Qxc4 dxc4 31. Be5 a3 32. Rg3 axb2+ 33. Rxb2 Kg8 34. Rc3 Bd5 35. Re3 Bh1 36. a3
2015-12-09 14&#58;16&#58;11.208 = Playing&#58; 30. Qxc4
2015-12-09 14&#58;16&#58;11.208 = FEN&#58; rB6/5k1p/4pPp1/2Pp4/p1QPb1P1/7P/PP1R4/2K3R1 b - - 0 30
2015-12-09 14&#58;16&#58;11.208 > tellothers &#91;+8.230/11/5.257/8,348,925&#93; 30. Qxc4 dxc4 31. Be5 a3 32. Rg3 axb2+ 33. Rxb2 Kg8 34. Rc3 Bd5 35. Re3 Bh1 36. a3
2015-12-09 14&#58;16&#58;11.208 > move Qxc4
2015-12-09 14&#58;16&#58;11.208 = Forced mode is enabled.
2015-12-09 14&#58;16&#58;11.208 < undo
2015-12-09 14&#58;16&#58;11.208 = New game
2015-12-09 14&#58;16&#58;11.208 > pong 12
bob
Posts: 20943
Joined: Mon Feb 27, 2006 7:30 pm
Location: Birmingham, AL

Re: xboard: Spurious undo after a new game and first move

Post by bob »

sje wrote:xboard: Spurious undo after a new game and first move

I've posted several cases of xboard issuing a spurious undo directive; here is a case where the undo is sent after a new game is started and after the opponent sends his first move. In all, there are fifteen directives sent between the resignation and the undo:

Code: Select all

2015-12-09 14&#58;15&#58;56.228 = FEN&#58; rB6/5k1p/4pPp1/2Pp4/pq1Pb1P1/7P/PP1R4/2K2QR1 b - - 0 29
2015-12-09 14&#58;15&#58;56.228 > move Bxb8
2015-12-09 14&#58;15&#58;57.725 < time 53900
2015-12-09 14&#58;15&#58;57.725 < otim 75100
2015-12-09 14&#58;15&#58;57.726 = Program time&#58; 8&#58;59.000
2015-12-09 14&#58;15&#58;57.726 < usermove Qc4+
2015-12-09 14&#58;15&#58;57.727 = Opponent time&#58; 12&#58;31.000
2015-12-09 14&#58;15&#58;57.727 = Playing&#58; 29... Qc4+
2015-12-09 14&#58;15&#58;57.727 = FEN&#58; rB6/5k1p/4pPp1/2Pp4/p1qPb1P1/7P/PP1R4/2K2QR1 w - - 1 30
2015-12-09 14&#58;15&#58;57.735 > 1 886 0 22 Qxc4 dxc4
2015-12-09 14&#58;15&#58;57.736 > 2 859 0 139 Qxc4 dxc4 Be5
2015-12-09 14&#58;15&#58;57.736 > 3 877 0 596 Qxc4 dxc4 Be5 a3
2015-12-09 14&#58;15&#58;57.738 > 4 806 0 2242 Qxc4 dxc4 Be5 a3 b3 cxb3 axb3
2015-12-09 14&#58;15&#58;57.744 > 5 814 1 9586 Qxc4 dxc4 Be5 a3 Rgd1 axb2+ Kxb2 Kg8
2015-12-09 14&#58;15&#58;57.758 > 6 811 2 28901 Qxc4 dxc4 Be5 a3 Re1 axb2+ Kxb2 Bc6
2015-12-09 14&#58;15&#58;57.806 > 7 810 7 102610 Qxc4 dxc4 Be5 a3 b3 cxb3 axb3 a2
2015-12-09 14&#58;15&#58;57.938 > 8 810 20 311200 Qxc4 dxc4 Be5 a3 b3 cxb3 axb3 a2 Kb2 Kg8
2015-12-09 14&#58;15&#58;58.425 > 9 817 69 1075404 Qxc4 dxc4 Be5 a3 Rg3 axb2+ Rxb2 Kg8 Bf4 Kh8
2015-12-09 14&#58;15&#58;59.451 > 10 814 171 2734419 Qxc4 dxc4 Be5 a3 Rg3 axb2+ Rxb2 Bc6 a3 Rd8 Re3
2015-12-09 14&#58;16&#58;02.989 > 11 823 525 8348925 Qxc4 dxc4 Be5 a3 Rg3 axb2+ Rxb2 Kg8 Rc3 Bd5 Re3 Bh1 a3
2015-12-09 14&#58;16&#58;04.996 < result 1-0 &#123;MR-LEE resigns&#125;

At this point, the game is over.



2015-12-09 14&#58;16&#58;04.997 < force
2015-12-09 14&#58;16&#58;04.997 < ping 12
2015-12-09 14&#58;16&#58;05.009 < new


This should start a new game...


2015-12-09 14&#58;16&#58;05.009 < random
2015-12-09 14&#58;16&#58;05.009 < ics 207.192.66.15
2015-12-09 14&#58;16&#58;05.009 < post
2015-12-09 14&#58;16&#58;05.009 < hard
2015-12-09 14&#58;16&#58;05.009 < easy
2015-12-09 14&#58;16&#58;05.009 < ping 13
2015-12-09 14&#58;16&#58;07.966 < level 0 15 0
2015-12-09 14&#58;16&#58;07.966 < name MR-LEE
2015-12-09 14&#58;16&#58;07.966 < rating 2245 1860
2015-12-09 14&#58;16&#58;10.013 < time 90000
2015-12-09 14&#58;16&#58;10.013 < otim 90000

Looks like a new game has been started at this point.



2015-12-09 14&#58;16&#58;10.013 < usermove c4

White plays c4, normal.

What is all the stuff below this point???  Looks like the engine is still in the middle of the last game, or else there might be a missing flush&#40;)/fflush&#40;) that leaves old data in the output buffer than gets pushed over when the engine does the next move or whatever???


2015-12-09 14&#58;16&#58;11.208 = &#91;+8.230/11/5.257/8,348,925&#93; 30. Qxc4 dxc4 31. Be5 a3 32. Rg3 axb2+ 33. Rxb2 Kg8 34. Rc3 Bd5 35. Re3 Bh1 36. a3
2015-12-09 14&#58;16&#58;11.208 = Playing&#58; 30. Qxc4
2015-12-09 14&#58;16&#58;11.208 = FEN&#58; rB6/5k1p/4pPp1/2Pp4/p1QPb1P1/7P/PP1R4/2K3R1 b - - 0 30
2015-12-09 14&#58;16&#58;11.208 > tellothers &#91;+8.230/11/5.257/8,348,925&#93; 30. Qxc4 dxc4 31. Be5 a3 32. Rg3 axb2+ 33. Rxb2 Kg8 34. Rc3 Bd5 35. Re3 Bh1 36. a3
2015-12-09 14&#58;16&#58;11.208 > move Qxc4
2015-12-09 14&#58;16&#58;11.208 = Forced mode is enabled.
2015-12-09 14&#58;16&#58;11.208 < undo
2015-12-09 14&#58;16&#58;11.208 = New game
2015-12-09 14&#58;16&#58;11.208 > pong 12
I made notes above. I don't understand the output from the chess engine...
D Sceviour
Posts: 570
Joined: Mon Jul 20, 2015 5:06 pm

Re: xboard: Spurious undo after a new game and first move

Post by D Sceviour »

It is not clear whether "= Forced mode is enabled" is sent from an engine or from WB. If it is the engine then something has to tell the engine to turn off the force mode. Crafty uses a boolean "force" flag to track this. WB is telling the engine to undo because the force mode is still enabled. There might be something wrong with <usermove c4. I use move c2c4 which seems to let WB know what the move is, and indicate both sides agree that force mode is turned off.
User avatar
sje
Posts: 4675
Joined: Mon Mar 13, 2006 7:43 pm

Decoding key

Post by sje »

Decoding key for Symbolic's log file output:

Field 1: UTC yyyy-mm-dd
Field 2: UTC hh:mm:ss:mmm
Field 3: "=" is internal message; "<" is output from xboard; ">" is output from Symbolic

Output from both xboard and Symbolic is logged as it is received/sent.

Symbolic processes directives in the order in which they are received. It does not start processing a given directive until the previous directive is processed. Also, it does not start processing a directive while in a search; the search must first complete. This means that it doesn't process an out-of-turn resignation until the search ends and its result (move/draw/resignation) is sent.

There is nothing in the xboard documentation which says that a search must abort if a result is received out of turn. Even the "." (move now) directive does not formally require a search to conclude early.

All text I/O is flushed at the end of each line.

Summary: Just because an xboard directive is echoed to the log file doesn't mean that Symbolic has started its processing.

xboard should never send an undo directive when connected to an ICS when the ICS has been configured with "no takeback". This would eliminate all the spurious undo directive instances reported to date.

xboard should wait for a pong for every ping it sends. Otherwise, why send the ping in the first place?
User avatar
sje
Posts: 4675
Joined: Mon Mar 13, 2006 7:43 pm

Re: xboard: Spurious undo after a new game and first move

Post by sje »

D Sceviour wrote:It is not clear whether "= Forced mode is enabled" is sent from an engine or from WB. If it is the engine then something has to tell the engine to turn off the force mode. Crafty uses a boolean "force" flag to track this. WB is telling the engine to undo because the force mode is still enabled. There might be something wrong with <usermove c4. I use move c2c4 which seems to let WB know what the move is, and indicate both sides agree that force mode is turned off.
The internal (not transmitted) message

Code: Select all

2015-12-09 14&#58;16&#58;11.208 = Forced mode is enabled.
is generated by Symbolic in response to the directive

Code: Select all

2015-12-09 14&#58;16&#58;04.997 < force
After sending

Code: Select all

2015-12-09 14&#58;16&#58;04.997 < ping 12
xboard sends more directives without waiting for pong 12. This continues with

Code: Select all

2015-12-09 14&#58;16&#58;05.009 < ping 13
and move directives, still without waiting for a pong 12. Eventually, Symbolic sends pong 12 and pong 13, but by then it would be too late if Symbolic had not ignored the undo directive.
bob
Posts: 20943
Joined: Mon Feb 27, 2006 7:30 pm
Location: Birmingham, AL

Re: Decoding key

Post by bob »

sje wrote:Decoding key for Symbolic's log file output:

Field 1: UTC yyyy-mm-dd
Field 2: UTC hh:mm:ss:mmm
Field 3: "=" is internal message; "<" is output from xboard; ">" is output from Symbolic

Output from both xboard and Symbolic is logged as it is received/sent.

Symbolic processes directives in the order in which they are received. It does not start processing a given directive until the previous directive is processed. Also, it does not start processing a directive while in a search; the search must first complete. This means that it doesn't process an out-of-turn resignation until the search ends and its result (move/draw/resignation) is sent.

There is nothing in the xboard documentation which says that a search must abort if a result is received out of turn. Even the "." (move now) directive does not formally require a search to conclude early.

All text I/O is flushed at the end of each line.

Summary: Just because an xboard directive is echoed to the log file doesn't mean that Symbolic has started its processing.

xboard should never send an undo directive when connected to an ICS when the ICS has been configured with "no takeback". This would eliminate all the spurious undo directive instances reported to date.

xboard should wait for a pong for every ping it sends. Otherwise, why send the ping in the first place?
It looks to me like you sent a move after the result and new commands. a move from the previous game, even after the new game was started and c4 was sent to you???
User avatar
hgm
Posts: 27798
Joined: Fri Mar 10, 2006 10:06 am
Location: Amsterdam
Full name: H G Muller

Re: Decoding key

Post by hgm »

Yes, he did, but that is allowed. XBoard should have realized the move belonged to the previous game because it came before the pong.

This problem was reported before, and the code in XBoard handling it seems pretty sick. I am not sure what exactly it is supposed to do (I mean, why would you ever want to undo moves in zippy mode?) So fixing this would probably break other things.
User avatar
sje
Posts: 4675
Joined: Mon Mar 13, 2006 7:43 pm

Dumping macports

Post by sje »

Getting xboard to run on a Mac like it runs under Linux requires use of the third party macports package. For various reasons, there are a huge number of dependencies generated in macports when xboard is installed. One of these is the openssl package, and within that package is some odd assembly language source, and some of that source uses an unusual opcode mnemonic. Unfortunately this mnemonic isn't supported by the assembler on Macs stuck at OS/X 10.7.5 or earlier because of Apple's refusal to support development tools or any other software on machines which are a single day more than five years old.

There might be some work-around eventually supplied by the macports guys, but I'm not holding my breath waiting for it to show. And it's disappointing that the macports crew claims support of OS/X 10.7.5 and earlier OS/X versions without having actually done any relevant, up-to-date testing. So I've pulled macports and xboard from my affected machines, leaving it only on the one OS/X 10.11.2 machine which connects to FICS and ICC. I'll pull it there, too, as soon as I get icsdrone up and running.
User avatar
sje
Posts: 4675
Joined: Mon Mar 13, 2006 7:43 pm

Re: Decoding key

Post by sje »

bob wrote:It looks to me like you sent a move after the result and new commands. a move from the previous game, even after the new game was started and c4 was sent to you???
The move was sent as soon as the search completed. This is always allowed, according to the documentation. Symbolic didn't start a new game until after it processed the new directive.

Received &#8800; Processed
User avatar
sje
Posts: 4675
Joined: Mon Mar 13, 2006 7:43 pm

Another bug

Post by sje »

Another bug, possibly related:

Symbolic has the class TokenList, a container for a two-way linked list of strings. It includes the instance method Arg(const unsigned int n) which returns the zero origin nth string. For each text line received from xboard, Symbolic creates an empty instance of TokenList and then loads it with white space separated tokens via its SimpleLoad instance method. This is a well-tested routine and has had almost no problems running successfully many thousands of times.

The exceptions, of which there have been perhaps three or four, seem to be correlated with out-of-turn resignations and the undo issue. Each time, the Arg method triggers an internal abort when it detects that the list contains fewer tokens than expected. In these cases, the first token is recognized as a valid xboard directive, but there is at least one parameter token missing.

Unfortunately, the exact input string was not output to Symbolic's log file before the internal abort was executed. I have since changed the code to fix this and am waiting for the bug to reappear.

The directive, whatever it was, came at the point where xboard should have sent a time/otim/usermove directive sequence. Perhaps a bogus result directive got sent. A line consisting entirely of white space might also be a problem.