CuteChessGUI v1.1.0: 'cancellation stall' abort.

[brinan]

Did not have any game aborts during this weekend's 14-game match stream.
The only change was unchecking Thinking on opponent's time (Ponder) box in Cute Chess GUI 1.1.0.

My own situation is now clarified. However, would like to help in resolving issue.

1. Any idea on the cause should be capable of explaining why problem arises only with long time controls.
Have run thousands of 10s+1s gauntlets untroubled, with pondering enabled and using Cute Chess GUI.
Current matches have a time control of 40m + 12s / move. There have been 3 trial runs and, now, 3 matches. Trouble-free only when turned off pondering in last match.

2. It might not be a bug in lc0's coding. Perhaps it's just a need for GUI to allow for an eccentricity in the implementation of the UCI protocol.

3. Read lc0 ponder stop issue again. Decided to compare my log output from Stockfish with same-situation output from lc0. Didn't see that lc0 omitted any responses, although it is more verbose.

Code: Select all

Stockfish 11
------------
GO PONDER:
<< bestmove g8f6 ponder c1g5
>> position startpos moves e2e4 e7e6 d2d4 d7d5 b1c3 g8f6 c1g5
>> isready
<< readyok
>> go ponder wtime 2380958 btime 2187085 winc 12000 binc 12000
<< info depth 1 seldepth 1 multipv 1 score cp -13 nodes 205 nps 102500 tbhits 0 time 2 pv d5e4

STOP:
<< info depth 23 seldepth 39 multipv 1 score cp -20 nodes 4220857 […]
>> stop
<< info depth 41 seldepth 5 multipv 1 score cp 0 nodes 430693475 […]
<< bestmove f8e7 ponder e4e5
>> position startpos moves e2e4 e7e6 d2d4 d7d5 b1c3 g8f6 e4e5
>> isready
<< readyok
>> go wtime 2391685 btime 2187085 winc 12000 binc 12000
<< info depth 1 seldepth 1 multipv 1 score cp 0 nodes 221 […]
-------------------------------------------------------------

lc0
---
GO PONDER:
0209 16:05:05.147405 9732 c:\projects\lc0\src\chess\uciloop.cc:219] << bestmove b1c3 ponder g8f6
0209 16:05:05.147428 9732 c:\projects\lc0\src\mcts\search.cc:624] End a watchdog thread.
0209 16:05:05.147932 8580 c:\projects\lc0\src\chess\uciloop.cc:132] >> position startpos moves e2e4 […]
0209 16:05:05.148004 8580 c:\projects\lc0\src\mcts\search.cc:646] Aborting search, if it is still active.
0209 16:05:05.702115 8580 c:\projects\lc0\src\mcts\search.cc:660] Search destroyed.
0209 16:05:05.702195 8580 c:\projects\lc0\src\chess\uciloop.cc:132] >> isready
0209 16:05:05.702234 8580 c:\projects\lc0\src\chess\uciloop.cc:219] << readyok
0209 16:05:05.702429 8580 c:\projects\lc0\src\chess\uciloop.cc:132] >> go ponder wtime 2380958 btime […]
0209 16:05:05.702527 8580 c:\projects\lc0\src\engine.cc:259] Timer started at 0209 16:05:05.702232
0209 16:05:05.702744 6816 c:\projects\lc0\src\mcts\search.cc:593] Start a watchdog thread.
0209 16:05:05.702914 4604 c:\projects\lc0\src\mcts\search.h:195] Started search thread.
0209 16:05:05.703077 8580 c:\projects\lc0\src\mcts\search.cc:560] Search started. 0ms already passed.
0209 16:05:05.703066 8264 c:\projects\lc0\src\mcts\search.h:195] Started search thread.
0209 16:05:05.808868 6816 c:\projects\lc0\src\chess\uciloop.cc:219] << info depth 20 seldepth 55 […]

STOP:
0209 16:25:52.933474 8864 c:\projects\lc0\src\chess\uciloop.cc:219] << info depth 30 seldepth 60 […]
0209 16:25:57.802444 8580 c:\projects\lc0\src\chess\uciloop.cc:132] >> stop
0209 16:25:57.802510 8580 c:\projects\lc0\src\mcts\search.cc:636] Stopping search due to `stop` uci command.
0209 16:25:57.802888 8864 c:\projects\lc0\src\chess\uciloop.cc:219] << info depth 30 seldepth 60 […]
0209 16:25:57.803551 8864 c:\projects\lc0\src\chess\uciloop.cc:219] << info string e7h4  (327 ) N: 1370245 […]
0209 16:25:57.803640 8864 c:\projects\lc0\src\mcts\search.cc:296] --- Opponent moves after: e7h4
0209 16:25:57.803836 8864 c:\projects\lc0\src\mcts\search.cc:301] e1e2  (106 ) N:    6582 […]
[…]
0209 16:25:57.804165 8864 c:\projects\lc0\src\chess\uciloop.cc:219] << bestmove e7h4 ponder d2f2
0209 16:25:57.804207 8864 c:\projects\lc0\src\mcts\search.cc:624] End a watchdog thread.
0209 16:25:57.804295 8580 c:\projects\lc0\src\chess\uciloop.cc:132] >> position startpos moves e2e4 […]
0209 16:25:57.804390 8580 c:\projects\lc0\src\mcts\search.cc:646] Aborting search, if it is still active.
0209 16:25:58.319534 8580 c:\projects\lc0\src\mcts\search.cc:660] Search destroyed.
0209 16:25:58.319626 8580 c:\projects\lc0\src\chess\uciloop.cc:132] >> isready
0209 16:25:58.319668 8580 c:\projects\lc0\src\chess\uciloop.cc:219] << readyok
0209 16:25:58.319927 8580 c:\projects\lc0\src\chess\uciloop.cc:132] >> go wtime 2170501 btime […]
0209 […]320011 8580 […]\mcts\stoppers\factory.cc:281] Budgeted time for the move: 60233.6ms(+397649ms to squander). Remaining time 2170501ms(-200ms overhead)
0209 16:25:58.320051 8580 c:\projects\lc0\src\engine.cc:259] Timer started at 0209 16:25:58.319666
0209 16:25:58.320328 1716 c:\projects\lc0\src\mcts\search.cc:593] Start a watchdog thread.
0209 16:25:58.320477 784 c:\projects\lc0\src\mcts\search.h:195] Started search thread.
0209 16:25:58.320645 8580 c:\projects\lc0\src\mcts\search.cc:560] Search started. 0ms already passed.
0209 16:25:58.320635 3104 c:\projects\lc0\src\mcts\search.h:195] Started search thread.
0209 16:25:58.433411 1716 c:\projects\lc0\src\chess\uciloop.cc:219] << info depth 23 seldepth 27 […]

[Modern Times]

2. It might not be a bug in lc0's coding. Perhaps it's just a need for GUI to allow for an eccentricity in the implementation of the UCI protocol.

From memory the cutechess developers were very clear that they would not do that. The engine strictly follows protocol, or it doesn't run.

[hgm]

And that is as it should be!

[brinan]

In terms of what to do about the issue, have no problem with last two views.

By the way, don't know where cancellation stall came from
Cute Chess GUI's error message in the pgn file is: White's (or Black's) connection stalls.

[Modern Times]

By the way, don't know where cancellation stall came from
Cute Chess GUI's error message in the pgn file is: White's (or Black's) connection stalls.

CCRL testers who use cutechess (with ponder off) have had this as well occasionally, depending on the engine. Including A/B engines.

I had it myself with the Zeta engine running on GPU.

[crem]

I don't see anything wrong in Lc0 logs. The engine receives ucinewgame, and doesn't respond to it because it must not. After that (from Lc0 point of view) nothing happens and the engine is killed. It's suspicious though that it always happens 15 seconds after previous response of Lc0, which may be that that response somehow doesn't reach the GUI.

Could you also post CuteChess logs with more context? It would be interesting how the same situation is seen from the other side.

[brinan]

crem
It's suspicious though that it always happens 15 seconds after previous response of Lc0, which may be that that response somehow doesn't reach the GUI.

Note, the wait between games in my more recent matches is 15 seconds.


Could you also post CuteChess logs with more context? It would be interesting how the same situation is seen from the other side.

Caught only one aborted game from Cute Chess. Note Stockfish is White for aborted game. Error message in pgn file refers to Black.
The GUI has a window for log entries. Window cleared every game. Can save window output to file. Has to be done manually.

Code: Select all

ABORTED GAME 14 (MATCH 2)
=========================

From Cute Chess GUI game logs
-----------------------------

End of previous game 13:
>lc0.net.62164(3): isready
>Stockfish 11(1): isready
<Stockfish 11(1): readyok
<lc0.net.62164(3): readyok

Log for aborted game 14:
>Stockfish 11(1): ucinewgame
>Stockfish 11(1): setoption name Ponder value true
<Stockfish 11(1): info string Found 510 tablebases
>Stockfish 11(1): isready
<Stockfish 11(1): readyok
>Stockfish 11(1): quit

Let me know if there is anything else I can do.

[crem]

crem
It's suspicious though that it always happens 15 seconds after previous response of Lc0, which may be that that response somehow doesn't reach the GUI.

Note, the wait between games in my more recent matches is 15 seconds.


Could you also post CuteChess logs with more context? It would be interesting how the same situation is seen from the other side.

Caught only one aborted game from Cute Chess. Note Stockfish is White for aborted game. Error message in pgn file refers to Black.
The GUI has a window for log entries. Window cleared every game. Can save window output to file. Has to be done manually.

Code: Select all

ABORTED GAME 14 (MATCH 2)
=========================

From Cute Chess GUI game logs
-----------------------------

End of previous game 13:
>lc0.net.62164(3): isready
>Stockfish 11(1): isready
<Stockfish 11(1): readyok
<lc0.net.62164(3): readyok

Log for aborted game 14:
>Stockfish 11(1): ucinewgame
>Stockfish 11(1): setoption name Ponder value true
<Stockfish 11(1): info string Found 510 tablebases
>Stockfish 11(1): isready
<Stockfish 11(1): readyok
>Stockfish 11(1): quit

Let me know if there is anything else I can do.

So, cutechess doesn't send anything to lc0 for game 14?

[brinan]

crem
So, cutechess doesn't send anything to lc0 for game 14?

No.

Debug window does not clear till new game starts. Game 14 was the last game.
Did not edit a thing.