xboard: Spurious undo directives

[sje]

xboard: Spurious undo directives

When playing on an ICS and the opponent resigns while the program is searching, xboard will emit a spurious undo directive AFTER it had already sent a new directive to start a new game.

This is double plus ungood, because a program has no move to retract when a new game is started. I suspect that this may have been the cause of some earlier crashes before I'd fixed Symbolic to ignore wacky undo directives.

[sje]

And perhaps a related problem is that a spurious undo directive may be sent after a new directive AND after a go directive when the program is playing as White.

This causes the program to retract its own move, then sit and wait until a timeout. This case is even worse because the program can't determine if the undo was spurious; the human on the other side of the ICS either has to wait a long time or forfeit via a disconnection.

[hgm]

This sounds very broken, I am amazed that no one else complained about this all these years. I will look into it. Do you happen to have an xboard.debug log where this happens?

[sje]

Alas, both the xboard log file and the Symbolic log file were overwritten. But it did happen as I stated, and there is absolutely no reason for an undo directive to show up when the ICS session is configured with no takeback allowed. Perhaps the problem is somehow timing dependent and perhaps I'm just about the only person using xboard+remote-human+ics+program on a Mac, so that could be why you haven't heard of it before.

Somehow a resignation out-of-turn (not likely to happen by a program, only by a human) is causing a delayed, unneeded undo.

[sje]

Possibly related: two pings without waiting for a pong:

Code: Select all

2015-09-13 00:30:45.965 < time 23800
2015-09-13 00:30:45.966 < otim 23600
2015-09-13 00:30:45.966 = Program time: 3:58.000
2015-09-13 00:30:45.966 < usermove Rbc1
2015-09-13 00:30:45.966 = Opponent time: 3:56.000
2015-09-13 00:30:45.966 = Playing: 18. Rbc1
2015-09-13 00:30:45.966 = FEN: r1b2rk1/pp4pp/2p1p3/4Pp2/2pP1P2/q1Nn1Q2/P4PBP/2R3RK b - - 9 18
2015-09-13 00:30:45.971 = C'tor: TabsSearch
2015-09-13 00:30:45.971 = C'tor: ComboVec
2015-09-13 00:30:45.977 > 1 775 0 8 Nxc1
2015-09-13 00:30:45.978 > 2 770 0 260 Nxc1 Qg3
2015-09-13 00:30:45.980 > 3 780 0 1120 Nxc1 Qg3 Bd7
2015-09-13 00:30:45.989 > 4 825 1 9845 Nxc1 Qg3 Rf7 Ne4 Qxg3 fxg3 Nxa2
2015-09-13 00:30:46.005 > 5 825 3 23877 Nxc1 Qg3 Rf7 Ne4 Qxg3 fxg3 Nxa2
2015-09-13 00:30:46.112 > 6 822 14 169388 Nxc1 Qg3 Rf7 Nd5 Qxg3 fxg3 Nxa2
2015-09-13 00:30:46.444 > 7 825 47 542380 Nxc1 Qg3 Rf7 Ne4 Qxg3 fxg3 Nxa2
2015-09-13 00:30:49.218 > 8 821 324 4490660 Nxc1 Qg3 Rf7 Ne4 Qxg3 fxg3 Nxa2 Nc5
2015-09-13 00:30:51.084 < result 0-1 {STS2 resigns}
2015-09-13 00:30:51.085 < force
2015-09-13 00:30:51.085 < ping 42
2015-09-13 00:30:51.097 < new
2015-09-13 00:30:51.097 < random
2015-09-13 00:30:51.097 < ics 207.192.66.15
2015-09-13 00:30:51.097 < post
2015-09-13 00:30:51.097 < hard
2015-09-13 00:30:51.097 < easy
2015-09-13 00:30:51.097 < ping 43
2015-09-13 00:30:51.925 = D'tor: ComboVec
2015-09-13 00:30:51.925 = D'tor: TabsSearch
2015-09-13 00:30:51.925 = C'tor: ComboVec
2015-09-13 00:30:51.927 = D'tor: ComboVec
2015-09-13 00:30:51.927 = [+8.214/8/3.246/4,490,660] 18... Nxc1 19. Qg3 Rf7 20. Ne4 Qxg3 21. fxg3 Nxa2 22. Nc5
2015-09-13 00:30:51.927 = Playing: 18... Nxc1
2015-09-13 00:30:51.927 = FEN: r1b2rk1/pp4pp/2p1p3/4Pp2/2pP1P2/q1N2Q2/P4PBP/2n3RK w - - 0 19
2015-09-13 00:30:51.927 > tellothers [+8.214/8/3.246/4,490,660] 18... Nxc1 19. Qg3 Rf7 20. Ne4 Qxg3 21. fxg3 Nxa2 22. Nc5
2015-09-13 00:30:51.927 > move Nxc1
2015-09-13 00:30:51.927 = Forced mode is enabled.
2015-09-13 00:30:51.927 = New game
2015-09-13 00:30:51.927 > pong 42
2015-09-13 00:30:51.927 = FEN: rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq - 0 1
2015-09-13 00:30:51.927 = Forced mode is disabled.
2015-09-13 00:30:51.927 = Pondering is disabled.
2015-09-13 00:30:51.927 = Posting is disabled.
2015-09-13 00:30:51.927 = Randomization is disabled.
2015-09-13 00:30:51.927 = Randomization is enabled.
2015-09-13 00:30:51.927 = ICS: 207.192.66.15
2015-09-13 00:30:51.927 = Posting is enabled.
2015-09-13 00:30:51.927 = Pondering is enabled.
2015-09-13 00:30:51.927 = Pondering is disabled.
2015-09-13 00:30:51.927 > pong 43

[hgm]

That is normal. In principle XBoard dosn't wait for pongs. They are just 'fences' in the data stream that make it possible for XBoard to deduce what are responses to commands sent before the ping, or to commands sent after it. In particular, XBoard must know when it sends the sequence usermove, force, result 1-0 {resign}, new, usermove, whether any move it receives is a response to the first usermove command (and thus belongs to the old game) or from the second (because the force aborted the engine's search in response to the first without producing a move). If it mistakes the move from the previous game for one from the new one, it leads to illegal moves in the latter.