I now have made a test version of UCI2WB that reports what it is doing on an independent log file. This gives me the following when starting Stockfish 10, pasting a game, and then switching on analysis mode:
Code: Select all
# queue 'protover', searching=0
# command protover
# uci
>> Stockfish 10 64 by T. Romstad, M. Costalba, J. Kiiski, G. Linscott
>> id name Stockfish 10 64
>> id author T. Romstad, M. Costalba, J. Kiiski, G. Linscott
>>
>> option name Debug Log File type string default
>> option name Contempt type spin default 24 min -100 max 100
>> option name Analysis Contempt type combo default Both var Off var White var Black var Both
>> option name Threads type spin default 1 min 1 max 512
>> option name Hash type spin default 16 min 1 max 131072
>> option name Clear Hash type button
>> option name Ponder type check default false
>> option name MultiPV type spin default 1 min 1 max 500
>> option name Skill Level type spin default 20 min 0 max 20
>> option name Move Overhead type spin default 30 min 0 max 5000
>> option name Minimum Thinking Time type spin default 20 min 0 max 5000
>> option name Slow Mover type spin default 84 min 10 max 1000
>> option name nodestime type spin default 0 min 0 max 10000
>> option name UCI_Chess960 type check default false
>> option name UCI_AnalyseMode type check default false
>> option name SyzygyPath type string default <empty>
>> option name SyzygyProbeDepth type spin default 1 min 1 max 100
>> option name Syzygy50MoveRule type check default true
>> option name SyzygyProbeLimit type spin default 7 min 0 max 7
>> uciok
# queue 'memory', searching=0
# command memory
# queue 'egtpath', searching=0
# command egtpath
# setoption name syzygyPath value ..\dtz50
# queue 'cores', searching=0
# command cores
# setoption name Threads value 1
# queue 'new', searching=0
# command new
# setoption name Hash value 68
# isready
# queue 'level', searching=0
# queue 'option', searching=0
# queue 'option', searching=0
# queue 'ping', searching=0
>> info string Found 0 tablebases
>> readyok
# ucinewgame
# command level
# command option
# setoption name Ponder value true
# command option
# setoption name Ponder value false
# command ping
# queue 'memory', searching=0
# command memory
# queue 'egtpath', searching=0
# command egtpath
# setoption name syzygyPath value ..\dtz50
# queue 'cores', searching=0
# command cores
# setoption name Threads value 1
# queue 'new', searching=0
# command new
# isready
>> info string Found 0 tablebases
# queue 'level', searching=0
# queue 'option', searching=0
# queue 'option', searching=0
# queue 'ping', searching=0
# queue 'force', searching=0
>> info string Found 0 tablebases
# queue 'quit', searching=0
# queue 'quit', searching=0
...
# queue 'quit', searching=0
# queue 'quit', searching=0
# queue 'quit', # queue 'protover', searching=0
# command protover
# uci
>> Stockfish 10 64 by T. Romstad, M. Costalba, J. Kiiski, G. Linscott
# queue 'memory', searching=0
>> id name Stockfish 10 64
>> id author T. Romstad, M. Costalba, J. Kiiski, G. Linscott
>>
>> option name Debug Log File type string default
>> option name Contempt type spin default 24 min -100 max 100
>> option name Analysis Contempt type combo default Both var Off var White var Black var Both
>> option name Threads type spin default 1 min 1 max 512
>> option name Hash type spin default 16 min 1 max 131072
>> option name Clear Hash type button
>> option name Ponder type check default false
>> option name MultiPV type spin default 1 min 1 max 500
>> option name Skill Level type spin default 20 min 0 max 20
>> option name Move Overhead type spin default 30 min 0 max 5000
>> option name Minimum Thinking Time type spin default 20 min 0 max 5000
>> option name Slow Mover type spin default 84 min 10 max 1000
>> option name nodestime type spin default 0 min 0 max 10000
>> option name UCI_Chess960 type check default false
>> option name UCI_AnalyseMode type check default false
# queue 'egtpath', searching=0
>> option name SyzygyPath type string default <empty>
>> option name SyzygyProbeDepth type spin default 1 min 1 max 100
>> option name Syzygy50MoveRule type check default true
>> option name SyzygyProbeLimit type spin default 7 min 0 max 7
>> uciok
# command memory
# command egtpath
# setoption name syzygyPath value ..\dtz50
# queue 'cores', searching=0
# command cores
# setoption name Threads value 1
# queue 'new', searching=0
# command new
# setoption name Hash value 68
# isready
# queue 'level', searching=0
# queue 'option', searching=0
# queue 'option', searching=0
# queue 'ping', searching=0
# queue 'force', searching=0
# queue 'analyze', searching=0
>> info string Found 0 tablebases
>> readyok
# ucinewgame
# command level
# command option
# setoption name Ponder value true
# command option
# setoption name Ponder value false
# command ping
# command force
# command analyze
# setoption name UCI_AnalyseMode value true
# position startpos moves d2d4 g8f6 c2c4 g7g6 b1c3 f8g7
# go infinite
>> info string Found 0 tablebases
>> info depth 1 seldepth 1 multipv 1 score cp 253 nodes 33 nps 16500 tbhits 0 time 2 pv e2e4
>> info depth 2 seldepth 2 multipv 1 score cp 275 nodes 70 nps 35000 tbhits 0 time 2 pv e2e4 a7a6
>> info depth 3 seldepth 3 multipv 1 score cp 338 nodes 114 nps 57000 tbhits 0 time 2 pv e2e4 b7b6 e4e5
>> info depth 4 seldepth 4 multipv 1 score cp 136 nodes 503 nps 251500 tbhits 0 time 2 pv c1g5 d7d6 e2e4 c7c6
>> info depth 5 seldepth 5 multipv 1 score cp 166 nodes 825 nps 275000 tbhits 0 time 3 pv e2e4 d7d6 f1e2 b8c6
...
An unintended effect that is revealed by this is that UCI2WB starts queueing zillions of 'quit' commands when WinBoard closes the pipes, so that it sees an End-Of-File on its input. I had intentionally fake it a 'quit' command in that situation to be sure everything will be handled orderly when a GUI dies without sending 'quit', but I had not realized that it would then keep doing that. (I snipped most of it out of the log.) This should not hurt, however. The sequence is interrupted somewhere in the middle, when WinBoard kills the adapter, to start a new one. The log of that new one is just appended, and starts with the "# queue 'protover', ...". So the issue is, why didn't the session before that terminate by itself?
It seems there is indeed some strange Stockfish behavior to blame for this:
The first 'new' command triggers sending of an 'isready', and Stockfish replies to this with
>> info string Found 0 tablebases
>> readyok
(The >> was prefixed by UCI2WB in the log to indicate raw engine input.) The 'level', 2x 'option' (from 'hard', 'easy') and 'ping' that were queued while waiting for 'readyok' are then released and executed. But after some more commands are processed as they should, a new 'new' command comes in, and causes sending of another 'isready'.
This second 'isready' is never acknowledged with a 'readyok' by stockfish; instead it tells again how many tablebases it has loaded. (Not sure what triggers that in the first place. "setoption Threads, perhaps?). After some time it even tells that for a third time. But never a 'readyok' appears, and UCI2WB would wait for that until doomsday.
It seems to me this is a clear UCI violation by Stockfish 10.