Stockfish hangs

[hgm]

I got a complaint that Stockfish forfeited on time in WinBoard. But looking at the debug log suggest that Stockfish is in error here. An excerpt:

StartChildProcess (dir=".") UCI2WB debug -nice 10 -kill 1 -c "stockfish_21011322_x64_modern.exe" "C:\WinBoard-4.6.2\Engines\stockfish_21011322_x64_modern"
29169 <second: # uci
29169 <second: # engine said: Stockfish 130121 by the Stockfish developers (see AUTHORS file)
29169 <second: # engine said: id name Stockfish 130121
29170 <second: # engine said: id author the Stockfish developers (see AUTHORS file)
29170 <second: # engine said:
29170 <second: # engine said: option name Debug Log File type string default
29171 <second: # engine said: option name Contempt type spin default 24 min -100 max 100
29172 <second: # engine said: option name Analysis Contempt type combo default Both var Off var White var Black var Both
29173 <second: # engine said: option name Threads type spin default 1 min 1 max 512
29174 <second: # engine said: option name Hash type spin default 16 min 1 max 33554432
29174 <second: # engine said: option name Clear Hash type button
29175 <second: # engine said: option name Ponder type check default false
29175 <second: # engine said: option name MultiPV type spin default 1 min 1 max 500
29176 <second: # engine said: option name Skill Level type spin default 20 min 0 max 20
29176 <second: # engine said: option name Move Overhead type spin default 10 min 0 max 5000
29177 <second: # engine said: option name Slow Mover type spin default 100 min 10 max 1000
29178 <second: # engine said: option name nodestime type spin default 0 min 0 max 10000
29179 <second: # engine said: option name UCI_Chess960 type check default false
29179 <second: # engine said: option name UCI_AnalyseMode type check default false
29180 <second: # engine said: option name UCI_LimitStrength type check default false
29180 <second: # engine said: option name UCI_Elo type spin default 1350 min 1350 max 2850
29181 <second: # engine said: option name UCI_ShowWDL type check default false
29182 <second: # engine said: option name SyzygyPath type string default <empty>
29182 <second: # engine said: option name SyzygyProbeDepth type spin default 1 min 1 max 100
29183 <second: # engine said: option name Syzygy50MoveRule type check default true
29184 <second: # engine said: option name SyzygyProbeLimit type spin default 7 min 0 max 7
29185 <second: # engine said: option name Use NNUE type check default true
29186 <second: # engine said: option name EvalFile type string default nn-62ef826d1a6d.nnue
29186 <second: # engine said: uciok
29201 <second: # setoption name Threads value 1
29202 <second: # setoption name Hash value 136
29202 <second: # isready
29449 <second: # engine said: readyok
29449 <second: # ucinewgame
29450 <second: # setoption name Ponder value true
29450 <second: # setoption name Ponder value false
31103 <second: # position startpos moves e2e4 e7e5 g1f3 b8c6 f1b5 a7a6 b5a4 g8f6 e1g1 f8e7 d2d3
31104 <second: # go btime 64480 wtime 64970 winc 1000 binc 1000
31104 <second: # engine said: info string NNUE evaluation using nn-62ef826d1a6d.nnue enabled

At that point Stockfish goes mute, and just allows the clock to tick away the time until it forfeits.

[tmokonen]

Very odd. It appears Stockfish issued the readyok before the nnue file was initialized, and missed some of the subsequent commands sent by the GUI.

[Joerg Oster]

I got a complaint that Stockfish forfeited on time in WinBoard. But looking at the debug log suggest that Stockfish is in error here. An excerpt:

StartChildProcess (dir=".") UCI2WB debug -nice 10 -kill 1 -c "stockfish_21011322_x64_modern.exe" "C:\WinBoard-4.6.2\Engines\stockfish_21011322_x64_modern"
29169 <second: # uci
29169 <second: # engine said: Stockfish 130121 by the Stockfish developers (see AUTHORS file)
29169 <second: # engine said: id name Stockfish 130121
29170 <second: # engine said: id author the Stockfish developers (see AUTHORS file)
29170 <second: # engine said:
29170 <second: # engine said: option name Debug Log File type string default
29171 <second: # engine said: option name Contempt type spin default 24 min -100 max 100
29172 <second: # engine said: option name Analysis Contempt type combo default Both var Off var White var Black var Both
29173 <second: # engine said: option name Threads type spin default 1 min 1 max 512
29174 <second: # engine said: option name Hash type spin default 16 min 1 max 33554432
29174 <second: # engine said: option name Clear Hash type button
29175 <second: # engine said: option name Ponder type check default false
29175 <second: # engine said: option name MultiPV type spin default 1 min 1 max 500
29176 <second: # engine said: option name Skill Level type spin default 20 min 0 max 20
29176 <second: # engine said: option name Move Overhead type spin default 10 min 0 max 5000
29177 <second: # engine said: option name Slow Mover type spin default 100 min 10 max 1000
29178 <second: # engine said: option name nodestime type spin default 0 min 0 max 10000
29179 <second: # engine said: option name UCI_Chess960 type check default false
29179 <second: # engine said: option name UCI_AnalyseMode type check default false
29180 <second: # engine said: option name UCI_LimitStrength type check default false
29180 <second: # engine said: option name UCI_Elo type spin default 1350 min 1350 max 2850
29181 <second: # engine said: option name UCI_ShowWDL type check default false
29182 <second: # engine said: option name SyzygyPath type string default <empty>
29182 <second: # engine said: option name SyzygyProbeDepth type spin default 1 min 1 max 100
29183 <second: # engine said: option name Syzygy50MoveRule type check default true
29184 <second: # engine said: option name SyzygyProbeLimit type spin default 7 min 0 max 7
29185 <second: # engine said: option name Use NNUE type check default true
29186 <second: # engine said: option name EvalFile type string default nn-62ef826d1a6d.nnue
29186 <second: # engine said: uciok
29201 <second: # setoption name Threads value 1
29202 <second: # setoption name Hash value 136
29202 <second: # isready
29449 <second: # engine said: readyok
29449 <second: # ucinewgame
29450 <second: # setoption name Ponder value true
29450 <second: # setoption name Ponder value false
31103 <second: # position startpos moves e2e4 e7e5 g1f3 b8c6 f1b5 a7a6 b5a4 g8f6 e1g1 f8e7 d2d3
31104 <second: # go btime 64480 wtime 64970 winc 1000 binc 1000
31104 <second: # engine said: info string NNUE evaluation using nn-62ef826d1a6d.nnue enabled

At that point Stockfish goes mute, and just allows the clock to tick away the time until it forfeits.

Exactly replicated all commands, no problem here.

Code: Select all

uciok
setoption name Threads value 1
setoption name Hash value 136
isready
readyok
ucinewgame
setoption name Ponder value true
setoption name Ponder value false
position startpos moves e2e4 e7e5 g1f3 b8c6 f1b5 a7a6 b5a4 g8f6 e1g1 f8e7 d2d3
go btime 64480 wtime 64970 winc 1000 binc 1000
info string NNUE evaluation using nn-62ef826d1a6d.nnue enabled
info depth 1 seldepth 1 multipv 1 score cp -22 nodes 35 nps 35000 tbhits 0 time 1 pv e8g8
info depth 2 seldepth 2 multipv 1 score cp -21 nodes 102 nps 102000 tbhits 0 time 1 pv d7d6 c2c3
info depth 3 seldepth 3 multipv 1 score cp -31 nodes 155 nps 155000 tbhits 0 time 1 pv d7d6 c2c3 e8g8
info depth 4 seldepth 4 multipv 1 score cp -25 nodes 270 nps 135000 tbhits 0 time 2 pv d7d6 a4c6 b7c6 c2c3
info depth 5 seldepth 5 multipv 1 score cp 0 nodes 360 nps 180000 tbhits 0 time 2 pv d7d6 c2c4 e8g8
info depth 6 seldepth 6 multipv 1 score cp 6 nodes 785 nps 392500 tbhits 0 time 2 pv d7d6 b1d2 e8g8 c2c3 g8h8 a4b3
info depth 7 seldepth 7 multipv 1 score cp -7 nodes 1006 nps 335333 tbhits 0 time 3 pv d7d6 b1d2 e8g8 c2c3 g8h8 a4b3 c8g4
info depth 8 seldepth 10 multipv 1 score cp -21 nodes 3270 nps 545000 tbhits 0 time 6 pv b7b5 a4b3 e8g8 c2c3 d7d5 e4d5 f6d5 f1e1
info depth 9 seldepth 12 multipv 1 score cp -23 nodes 7497 nps 576692 tbhits 0 time 13 pv b7b5 a4b3 e8g8 a2a4 b5b4 b1d2 d7d6 f1e1 c6a5
info depth 10 seldepth 13 multipv 1 score cp -25 nodes 17629 nps 652925 tbhits 0 time 27 pv b7b5 a4b3 d7d6 a2a4 c6a5 b3a2 e8g8 b1c3 b5b4 c3d5 f6d5 a2d5
info depth 11 seldepth 15 multipv 1 score cp -18 nodes 29267 nps 696833 tbhits 0 time 42 pv b7b5 a4b3 d7d6 a2a4 b5b4 c2c3 b4c3 b2c3 c6a5 b3a2 e8g8 b1d2
info depth 12 seldepth 17 multipv 1 score cp -22 nodes 64033 nps 719471 tbhits 0 time 89 pv b7b5 a4b3 d7d6 a2a4 b5b4 c2c3 b4c3 b2c3 e8g8 b3c2 d6d5 b1d2 d5e4 d3e4
info depth 13 seldepth 18 multipv 1 score cp -27 nodes 87566 nps 729716 tbhits 0 time 120 pv b7b5 a4b3 d7d6 a2a4 b5b4 c2c3 e8g8 b1d2 c6a5 b3c2 b4c3 b2c3 c7c5 d3d4 e5d4 c3d4 c5d4
info depth 14 seldepth 21 multipv 1 score cp -44 nodes 157780 nps 751333 tbhits 0 time 210 pv b7b5 a4b3 a6a5 a2a4 b5b4 b1d2 e7c5 d2c4 d7d6 c2c3 e8g8 d3d4 e5d4
info depth 15 seldepth 19 multipv 1 score cp -47 nodes 185272 nps 759311 tbhits 0 time 244 pv b7b5 a4b3 d7d6 a2a4 b5b4 c2c3 e8g8 b1d2 d6d5 f1e1 a8b8 a4a5 b4c3 b2c3 c8e6 d3d4
info depth 16 seldepth 23 multipv 1 score cp -41 nodes 230071 nps 761824 tbhits 0 time 302 pv b7b5 a4b3 d7d6 a2a4 b5b4 c2c3 e8g8 b1d2 c8e6 b3e6 f7e6 d3d4 d8d7 f1e1 b4c3 b2c3 e5d4 c3d4
info depth 17 seldepth 24 multipv 1 score cp -31 nodes 308965 nps 759127 tbhits 0 time 407 pv b7b5 a4b3 d7d6 c2c3 e8g8 h2h3 c8d7 b3c2 a6a5 d3d4 a5a4 b1a3 e5d4 c3d4
info depth 18 seldepth 22 multipv 1 score cp -26 nodes 413172 nps 760906 tbhits 0 time 543 pv b7b5 a4b3 d7d6 a2a4 b5b4 c2c3 e8g8 b1d2 a8b8 h2h3 c6a5 b3c2 c7c5 d3d4 b4c3 b2c3 e5d4 c3d4 c5d4 f3d4
info depth 19 seldepth 26 multipv 1 score cp -27 nodes 561514 nps 757778 tbhits 0 time 741 pv b7b5 a4b3 d7d6 c2c3 e8g8 f1e1 c6a5 b3c2 c7c5 d3d4 d8c7 d4d5 c8d7 a2a4 c5c4 a4b5 a6b5 b1d2 f8b8 d2f1
info depth 20 seldepth 27 multipv 1 score cp -22 nodes 755317 nps 766041 tbhits 0 time 986 pv b7b5 a4b3 d7d6 c2c3 e8g8 a2a4 b5b4 b1d2 a8b8 d3d4 c8g4 d1c2 b4c3 b2c3 e5d4 f3d4 c6a5 b3a2 c7c5 d4f5 g4f5 e4f5 a5c6
info depth 21 seldepth 28 multipv 1 score cp -16 nodes 1025197 nps 767363 hashfull 56 tbhits 0 time 1336 pv b7b5 a4b3 d7d6 c2c3 e8g8 f1e1 c6a5 b3c2 c7c5 d3d4 d8c7 d4d5 c8d7 h2h3 a5b7 c3c4 b7a5 b1d2 a5c4 d2c4 b5c4 d1e2 f8b8 e2c4 e7f8
info depth 22 seldepth 31 multipv 1 score cp -28 nodes 1287949 nps 765269 hashfull 67 tbhits 0 time 1683 pv b7b5 a4b3 d7d6 c2c3 e8g8 f1e1 c6a5 b3c2 c7c5 h2h3 a5c6 d3d4 e5d4 c3d4 c6b4 b1c3 b4c2 d1c2 c8b7 d4d5 h7h6 b2b3 a8c8 c1e3
info depth 23 seldepth 34 multipv 1 score cp -33 nodes 1665880 nps 763814 hashfull 91 tbhits 0 time 2181 pv b7b5 a4b3 d7d6 a2a4 b5b4 b1d2 c6a5 b3a2 c7c5 c2c3 a8b8 d3d4 d8c7 d4e5 d6e5 d2c4 a5c4 a2c4 f6e4 c4d5
info depth 24 seldepth 29 multipv 1 score cp -34 nodes 1831656 nps 763190 hashfull 100 tbhits 0 time 2400 pv b7b5 a4b3 d7d6 a2a4 b5b4 b1d2 c6a5 b3a2 c7c5 c2c3 e8g8 c3b4 c5b4 d2c4 a5c4 a2c4 a6a5 h2h3 c8d7 c1e3 a8c8 c4b3 g8h8
bestmove b7b5 ponder a4b3

Looks like the problem is NOT on the side of Stockfish.

Just some remarks.
Sending Ponder on and off consecutively is kinda weird.
You can always send 'go wtime btime winc binc', no need to change order here depending on which side to move.
'ucinewgame' should be followed by an 'isready'. Though I know the example given in the specs doesn't follow this, either.

[hgm]

Thanks for checking it out.

The Ponder-on-off madness is a legacy of the WinBoard kludge to cater to some non-compliant engines, for whch the ponder-off command ('easy' in CECP) was a toggle. It shouldn't be harmful, though.
Many Shogi engines crash instantly when you send wtime before btime. So I always send btime first, which in UCI should be allowed.
The ucinewgame issue is a point of concern. Many USI engines will not respond to 'isready' at this stage. This recommendation seems mostly for the benefit of the GUI, to more accurately determine when to start the engine's clock. I decided WinBoard could do without such synchronisation; If the engine wants to do something at this point that consumes significant time, I see no good reason why that time shouldn't be charged to it.

[Ras]

The ucinewgame issue is a point of concern.

It's actually pretty clear. From the UCI spec:

As the engine's reaction to "ucinewgame" can take some time the GUI should always send "isready" after "ucinewgame" to wait for the engine to finish its operation.

if Winboard isn't conforming to the UCI spec and the missing "isready" is indeed the reason, then it's not Stockfish's problem.

[hgm]

Perhaps I should simply refrain from sending 'ucinewgame'? Since there was no earlier game, this seems to comply even with the newer specs.

[Ras]

Perhaps I should simply refrain from sending 'ucinewgame'?

That might solve the problem with this one, not sure, but you'd run into the same problem upon the next game. Of course you can also leave it out there, too, but then the engine would keep its hashes, history and whatnot from the previous game. Depending on the engine, that may reduce the playing strength, but surely would lead to issues with reproducing games.

[hgm]

UCI2WB specifies reuse=0, so there won't be a next game for this instance of the engine.

[Michel]

Very odd. It appears Stockfish issued the readyok before the nnue file was initialized, and missed some of the subsequent commands sent by the GUI.

The message

info string NNUE evaluation using nn-62ef826d1a6d.nnue enabled

has nothing to do with the initialization of NNUE. This message is printed after every go command.

In fact I don't think NNUE needs any initialization.

[Joerg Oster]

Thanks for checking it out.

The Ponder-on-off madness is a legacy of the WinBoard kludge to cater to some non-compliant engines, for whch the ponder-off command ('easy' in CECP) was a toggle. It shouldn't be harmful, though.
Many Shogi engines crash instantly when you send wtime before btime. So I always send btime first, which in UCI should be allowed.

That's correct, yet unusual. But if they don't want to fix their engines there is not much you can do about.

The ucinewgame issue is a point of concern. Many USI engines will not respond to 'isready' at this stage. This recommendation seems mostly for the benefit of the GUI, to more accurately determine when to start the engine's clock. I decided WinBoard could do without such synchronisation; If the engine wants to do something at this point that consumes significant time, I see no good reason why that time shouldn't be charged to it.

That's a bit unfortunate, isn't it?
Especially nowadays, where loading EGTBs and Neural Nets might take a noticeable amount of time ...

When do you start the clock during a game?
After sending the position, or after sending the go command?
Anyways, I don't see a good reason to treat the start of a game different in that regard.