Warning on unexpected output #472
Description
The following snippet from the -debug output shows an 'Illegal PV move' warning:
92477 >cluster(0): position startpos moves d2d4 d7d5 c2c4 e7e6 g1f3 g8f6 c1g5 h7h6 g5f6 d8f6 b1c3 c7c6 d1b3 b8d7 a1d1 f6e7 e2e3 g7g6 f1d3 f8g7 e1g1 d5c4 b3c4 e8g8 f1e1 c6c5 a2a4 a7a6 c4b3 a8b8 d4d5 d7e5 f3e5 g7e5 a4a5 e5c3 b2c3 e6d5 b3d5 c8g4 d1a1 b8d8 d5e4 f8e8 e4e7 e8e7 d3c4 g4e6 c4e6 e7e6 g1f1 d8d3 e1c1 c5c4 f1e2 e6e5 c1c2 g8g7 h2h4 d3d5 a1b1 e5e7 c2a2 d5d3 a2a3 e7d7 b1b2 d7d5 g2g3 d5b5 b2b5 a6b5 a3a2 d3c3 a2b2 c3a3 b2b5 a3a2 e2f3 c4c3 b5b7 a2a5 b7c7 a5a3 g3g4 g7f6 f3e4 a3a4 e4f3 a4a3 g4g5 h6g5 c7c6 f6e5 h4g5 a3b3 c6c5 e5e6 f3e4 e6d6 c5c4 b3b5 c4c3 b5e5 e4d4 e5g5 c3b3 g5d5 d4e4 d5c5 e4f4 g6g5 f4g4 f7f6 f2f3 c5a5 g4h5 a5f5 h5g4 f5a5
92477 >cluster(0): isready
92478 <cluster(0): readyok
92478 >cluster(0): go wtime 1328 btime 1265 winc 100 binc 100
92502 <cluster(0): info depth 1 seldepth 1 multipv 1 score cp 0 nodes 2923 nps 116920 tbhits 0 time 25 pv g4h5
92533 <cluster(0): info depth 24 seldepth 25 multipv 1 score cp 0 nodes 7638236 nps 146889153 tbhits 0 time 52 pv e3e4 d6e5 b3b6 a5c5 b6a6 c5c1 a6a5 e5e6 a5a4 e6f7 a4a7 f7g6 a7a6 c1c5 g4g3 g6f7 a6a7 f7e6 g3f2 e6e5 a7a6 f6f5 e4f5 e5f5 a6a4
92533 <cluster(0): bestmove e3e4 ponder d6e5
92533 >master(1): position startpos moves d2d4 d7d5 c2c4 e7e6 g1f3 g8f6 c1g5 h7h6 g5f6 d8f6 b1c3 c7c6 d1b3 b8d7 a1d1 f6e7 e2e3 g7g6 f1d3 f8g7 e1g1 d5c4 b3c4 e8g8 f1e1 c6c5 a2a4 a7a6 c4b3 a8b8 d4d5 d7e5 f3e5 g7e5 a4a5 e5c3 b2c3 e6d5 b3d5 c8g4 d1a1 b8d8 d5e4 f8e8 e4e7 e8e7 d3c4 g4e6 c4e6 e7e6 g1f1 d8d3 e1c1 c5c4 f1e2 e6e5 c1c2 g8g7 h2h4 d3d5 a1b1 e5e7 c2a2 d5d3 a2a3 e7d7 b1b2 d7d5 g2g3 d5b5 b2b5 a6b5 a3a2 d3c3 a2b2 c3a3 b2b5 a3a2 e2f3 c4c3 b5b7 a2a5 b7c7 a5a3 g3g4 g7f6 f3e4 a3a4 e4f3 a4a3 g4g5 h6g5 c7c6 f6e5 h4g5 a3b3 c6c5 e5e6 f3e4 e6d6 c5c4 b3b5 c4c3 b5e5 e4d4 e5g5 c3b3 g5d5 d4e4 d5c5 e4f4 g6g5 f4g4 f7f6 f2f3 c5a5 g4h5 a5f5 h5g4 f5a5 e3e4
92534 >master(1): isready
92534 <master(1): readyok
92534 >master(1): go wtime 1373 btime 1265 winc 100 binc 100
92535 <master(1): info depth 1 seldepth 1 multipv 1 score cp 0 nodes 1455 nps 1455000 tbhits 0 time 1 pv d6e5
Warning: Illegal PV move g4h5 from cluster
Warning: Illegal PV move g4h5 from cluster
Warning: Illegal PV move g4h5 from cluster
Warning: Illegal PV move g4h5 from cluster
Warning: Illegal PV move g4h5 from cluster
Warning: Illegal PV move g4h5 from cluster
92539 <cluster(0): info depth 2 seldepth 2 multipv 1 score cp 0 nodes 5307 nps 212280 tbhits 0 time 25 pv g4h5 d6e6
Warning: Illegal PV move g4h5 from cluster
92540 <cluster(0): info depth 3 seldepth 4 multipv 1 score cp 0 nodes 7825 nps 313000 tbhits 0 time 25 pv g4h5 a5f5 h5g4
92541 <cluster(0): info depth 4 seldepth 4 multipv 1 score cp 0 nodes 10050 nps 402000 tbhits 0 time 25 pv g4h5 a5f5 h5g4
92541 <cluster(0): info depth 5 seldepth 7 multipv 1 score cp 0 nodes 13205 nps 528200 tbhits 0 time 25 pv g4h5 a5f5 h5g4
92541 <cluster(0): info depth 6 seldepth 4 multipv 1 score cp 0 nodes 16677 nps 667080 tbhits 0 time 25 pv g4h5 a5f5 h5g4
What is going on is not really an Illegal PV move (it is legal for the latest position that cluster received), but rather, cluster is sending info lines (containing PVs) after it has send a bestmove already. While this is obviously an engine issue (with non-synced IO between processes), it would be nice to have another error message for this.