Possible time control bug

[ChrisWhittington]

Hi Matties,

I was doing some fast play test with a completely brain dead broken version of mine against a six opponent pool, Rubichess being one. Mine lost every single game against everything (1000 games) except for three against Rubichess (RubiChess-20220223_x86-64-avx2.exe), so, investigated ....
Reason for the loss was the same each time. RubiChess blundered at the 40 move time control in each game. Example below. You can see that at move 40 it just plays 40. Kxb2 {-1.60/14 0.25s} Qxd1 41. Qxd1 {+9.25/16 0.19s}, seemingly Cutechess did not pick up either a score or a time. Time control 40/40.
This isn't a request to fix, it's just an alert in case its something you don't already know about.
Friendly greetings, Chris Whittington

[Event "?"]
[Site "?"]
[Date "2022.07.09"]
[Round "27"]
[White "Chess-System-Tal-1.35"]
[Black "RubiChess_2.2"]
[Result "1-0"]
[ECO "E60"]
[GameDuration "00:00:27"]
[GameEndTime "2022-07-09T15:07:54.222 W. Europe Summer Time"]
[GameStartTime "2022-07-09T15:07:26.321 W. Europe Summer Time"]
[Opening "King's Indian defense"]
[PlyCount "113"]
[TimeControl "40/10"]

1. d4 {book} Nf6 {book} 2. c4 {book} g6 {book} 3. f3 {book} Bg7 {book}
2. e4 {book} d6 {book} 5. Nc3 {book} O-O {book} 6. Bg5 {book} a6 {book}
3. Qd2 {book} Nbd7 {book} 8. O-O-O {book} c6 {book} 9. Kb1 {-0.05/14 0.58s}
   Qc7 {-0.19/21 0.73s} 10. Nge2 {+0.12/14 0.33s} b5 {+0.05/19 0.33s}
4. Ng3 {+0.19/13 0.25s} Rb8 {+0.35/20 0.55s} 12. Rc1 {+0.02/15 0.56s}
   bxc4 {+0.52/20 0.87s} 13. Bxc4 {-0.24/12 0.24s} a5 {+0.27/20 0.50s}
5. Rhd1 {+0.20/14 0.46s} Qa7 {+0.53/19 0.35s} 15. Be2 {+0.05/12 0.54s}
   Ba6 {+0.65/18 0.34s} 16. Rc2 {-0.01/14 0.52s} a4 {+0.59/19 0.23s}
6. Bxa6 {+0.03/16 0.42s} Qxa6 {+0.63/18 0.21s} 18. Bh6 {+0.07/16 0.20s}
   Bxh6 {+0.78/18 0.25s} 19. Qxh6 {-0.09/15 0.20s} Rb4 {+1.00/20 0.21s}
7. Qg5 {+0.30/13 0.22s} a3 {0.00/19 0.53s} 21. Nf5 {+0.39/13 0.22s}
   Rxb2+ {+0.25/19 0.52s} 22. Rxb2 {+0.56/14 0.20s} axb2 {0.00/20 0.42s}
8. Nxe7+ {+0.61/15 0.38s} Kg7 {0.00/23 0.30s} 24. Nf5+ {+0.71/12 0.32s}
   Kg8 {0.00/25 0.28s} 25. e5 {+0.46/13 0.32s} Nd5 {+0.96/19 0.22s}
9. Ne7+ {+0.40/16 0.48s} Kg7 {+1.15/21 0.34s} 27. Nexd5 {+0.28/15 0.26s}
   cxd5 {+0.91/18 0.33s} 28. exd6 {-0.01/14 0.37s} Qc4 {+1.81/21 0.34s}
10. Qe3 {0.00/16 0.17s} Rc8 {+2.27/19 0.23s} 30. Rd3 {-0.34/17 0.17s}
    Qb4 {+2.98/19 0.22s} 31. h3 {-0.39/14 0.44s} Nb6 {+3.11/23 0.28s}
11. d7 {-1.07/14 0.40s} Nc4 {+2.88/23 0.22s} 33. Qe5+ {-2.25/16 0.27s}
    Nxe5 {+2.81/22 0.22s} 34. dxc8=Q {-2.25/15 0.14s} Nxd3 {+2.73/22 0.22s}
12. g4 {-2.03/14 0.21s} h6 {+2.72/22 0.18s} 36. Qc7 {-2.17/14 0.34s}
    g5 {+2.44/19 0.18s} 37. Qc8 {-2.09/16 0.17s} Qxd4 {+2.12/18 0.12s}
13. Nd1 {-1.87/15 0.16s} Ne5 {+1.96/20 0.10s} 39. Qc2 {-1.71/12 0.13s}
    Qg1 {+2.31/17 0.077s} 40. Kxb2 {-1.60/14 0.25s} Qxd1 41. Qxd1 {+9.25/16 0.19s}
    Ng6 {-13.86/19 0.49s} 42. Qxd5 {+9.79/18 0.32s} Nf4 {-14.24/18 0.22s}
14. Qe5+ {+9.94/17 0.19s} Kg8 {-15.51/19 0.48s} 44. Kb3 {+10.51/18 0.19s}
    Ng6 {-15.41/18 0.52s} 45. Qf6 {+12.05/18 0.36s} Nf8 {-17.07/19 0.34s}
15. Qxh6 {+13.01/18 0.19s} Ne6 {-18.83/21 0.53s} 47. Ka4 {+13.39/19 0.19s}
    Ng7 {-18.46/20 0.47s} 48. Qxg5 {+13.59/19 0.18s} Kf8 {-18.91/22 0.37s}
16. Qd8+ {+16.03/19 0.19s} Ne8 {-18.91/1 0s} 50. Ka5 {+17.27/19 0.19s}
    f6 {-24.86/21 0.38s} 51. h4 {+M41/23 0.23s} Kf7 {-24.08/22 0.35s}
17. Qd7+ {+M15/32 0.14s} Kf8 {-26.80/21 0.19s} 53. h5 {+M11/39 0.17s}
    f5 {-28.99/20 0.51s} 54. g5 {+M9/40 0.13s} Nc7 {-M16/16 0.067s}
18. g6 {+M3/93 0.13s} Kg8 {-M4/4 0s} 56. Qf7+ {+M1/116 0.022s} Kh8 {-M4/1 0s}
19. Qf8# {0.00/116 0.008s, White mates} 1-0

[Matthies]

Hi Chris.

Thanks for the report, always appreciated.
Since the 20220223 release I have applied several patches for the time management to improve playing very fast time controls and also the moves/time control should have become better.

I played 200 40/10 games 20220223 vs. 20220706 (current master). Following graphs show that time trouble near move 40, 80, ... should be fixed.

[ChrisWhittington]

Thanks and those graphs are a cool tool. I wondered, btw, if the behaviour in cutechess wasn't the famous iteration zero explosion problem at short time control. Engine comes back without a PV or score (hence the empty cutechess field), but does return a move (possibly just whatever is at head of legal movelist)?
There are several ways to fix this, if so.
First is to prevent any search interrupt on the first iteration, and second, alongside the first, is to stop explosions at first iteration by switching off any check extensions in qsearch. Mine actually reduces extension possibilities for the first three iterations, the idea being to at least get something sensible back if minimum time.

[Matthies]

I guess Rubi was completely out of time and just returned a default move (first move of move list). The best solution is probably just to preserve some time for the remaining move(s) which is not too difficult at moves/time and which I hopefully have solved now. Interestingly current Stockfish has the same problem. I watched an out-of-time blunder at Grahams broadcast and reported to SF developers who track it here: official-stockfish/Stockfish#4000 but they seem focused on time+increment control and not very interested in solving the issue.
I will close this now.