tune.py: Include best values to debug log file

[fsmosca]

Suggestion

When -debug is set, also save the best values to debug log file.

This goes to console.

        print(f'Best expectation (κ={kappa}): {X[i]}'
              f' = {y_pred[i]/2:.3f} ± {sigma[i]/2:.3f}'
              f' (ELO-diff {elo:.3f} ± {pm:.3f})')

This goes to debug log file.
logging.info (...

[fsmosca]

I have a commit to fix this issue at
https://github.com/fsmosca/fastchess/commit/9a0a6631457093f361b9a15b012eecc7dffbd1fe
Do you want me to submit a pull request?

[thomasahle]

It's a question of what exactly the difference should be between the debugfile and simply the standard output. If one wants to save stdout to a file as well as the terminal, that's pretty easy to do.
What does cutechess do?

[fsmosca]

It is more of a convenience and peace of mind that logs are saved to a file by just specifying,
-debug tuner_log.txt while at the same time you can see the output from console those messages that are intended for console.

Cutechess-cli has debug and stderr.

[thomasahle]

So I think -debug has quite a performance impact, since it puts the engines into debug mode and saves all the communication. I wouldn't want to encourage enabling it by default for peace of mind.

Which things does cutechess send to stdout, stderr and debug respectively?

[fsmosca]

Most uci engines does not implement the debug option as recommended by uci protocol. Engine authors instead implement its own logging. Example Stockfish, Komodo, Andscacs, Fire and others even my engine Deuterium, I also don't support the debug option.

If there is such a uci engine that implements debug option, the engine will only enable its debugging when it receives a command,
setoption name debug value true
In this case engine performance will be affected.

Python-chess implements logging by only printing what the engine has normally sent.
Here is an example log from engine module of python-chess, and log from arena module. I add logging in arena.py. The engine is Deuterium and it says 'info time 716' after the search and according to arena log,
arena - INFO - elapse: 718
In other positions there is only a small difference.

2019-09-08 21:39:35,609 - arena - INFO - stm_engine: tuned_engine, time_left before search: 28856
2019-09-08 21:39:35,609 - engine - DEBUG - <UciProtocol (pid=6380)>: << position startpos moves d2d4 d7d5 c2c4 e7e6 b1c3 g8f6 c4d5 e6d5 c1g5 f8e7 e2e3 e8g8 g5f6 e7f6
2019-09-08 21:39:35,610 - engine - DEBUG - <UciProtocol (pid=6380)>: << go wtime 28855 btime 29121 winc 100 binc 100
2019-09-08 21:39:35,610 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 1 seldepth 5 multipv 1 score cp 41 time 1 nodes 57 nps 57000 pv f1d3
2019-09-08 21:39:35,610 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 2 seldepth 5 multipv 1 score cp 63 time 1 nodes 113 nps 113000 pv f1d3 c7c6 g1f3
2019-09-08 21:39:35,611 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 3 seldepth 6 multipv 1 score cp -9 time 1 nodes 497 nps 497000 pv f1d3 c7c6 e1f1 g7g6
2019-09-08 21:39:35,611 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 4 seldepth 5 multipv 1 score cp 21 time 1 nodes 526 nps 526000 pv f1d3
2019-09-08 21:39:35,611 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 4 seldepth 7 multipv 1 score cp 44 time 1 nodes 724 nps 724000 pv f1d3 g7g6 d1b3 c7c6 g1f3
2019-09-08 21:39:35,612 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 5 seldepth 7 multipv 1 score cp 30 time 2 nodes 1316 nps 658000 pv f1d3 c7c6 g1f3 c8g4 e1g1 b8d7
2019-09-08 21:39:35,615 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 6 seldepth 11 multipv 1 score cp 8 time 4 nodes 3906 nps 976500 pv f1e2 c7c6 g1f3 c8e6 e1g1 b8d7
2019-09-08 21:39:35,619 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 7 seldepth 11 multipv 1 score cp 18 time 8 nodes 7243 nps 905375 pv f1e2 c7c6 g1f3 c8f5 e1g1 b8d7 e2d3
2019-09-08 21:39:35,628 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 8 seldepth 13 multipv 1 score cp 24 time 18 nodes 15652 nps 869555 pv d1b3 c7c6 f1d3 b8d7 g1f3 d7b6 e1g1 c8g4
2019-09-08 21:39:35,639 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 9 seldepth 15 multipv 1 score cp 1 time 29 nodes 25732 nps 887310 pv f1e2 c7c6 g1f3 c8g4 d1b3 b7b5 f3e5 g4e2 e1e2 f6e5 d4e5
2019-09-08 21:39:35,671 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 10 seldepth 17 multipv 1 score cp 22 time 61 nodes 55448 nps 908983 pv g1f3 c8g4 f1e2 c7c6 e1g1 g4f3 e2f3 b8d7 d1b3 d7b6 a1c1
2019-09-08 21:39:35,709 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 11 seldepth 14 multipv 1 score cp -8 time 98 nodes 88222 nps 900224 pv g1f3
2019-09-08 21:39:35,715 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 11 seldepth 16 multipv 1 score cp 18 time 105 nodes 96313 nps 917266 pv g1f3 c8g4 f1e2 c7c6 d1b3 b7b5 e1g1 a7a5 f3e5 g4e2 c3e2 f6e5 d4e5
2019-09-08 21:39:35,751 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 12 seldepth 20 multipv 1 score cp 0 time 141 nodes 131119 nps 929921 pv g1f3 c8g4 f1e2 c7c6 d1b3 d8b6 e1g1 b8d7 b3c2 g4f3 e2f3 a8e8
2019-09-08 21:39:35,888 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 13 seldepth 21 multipv 1 score cp -7 time 278 nodes 246506 nps 886712 pv g1f3 c8g4 f1e2 c7c6 d1b3 d8b6 e1g1 b6b3 a2b3 b8d7 f1c1 g4f5 g1h1
2019-09-08 21:39:35,982 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 14 seldepth 19 multipv 1 score cp -4 time 372 nodes 330606 nps 888725 pv g1f3 c8g4 f1e2 c7c6 e1g1 g4f3 e2f3 b8d7 f3g4 f8e8 g4d7 d8d7 a1c1 g7g6
2019-09-08 21:39:36,327 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info depth 15 seldepth 23 multipv 1 score cp -12 time 716 nodes 604590 nps 844399 pv g1f3 c8g4 f1e2 c7c6 e1g1 g4f3 e2f3 b8d7 f3g4 d7b6 d1c2 g7g6 a2a4 f8e8 a1c1
2019-09-08 21:39:36,327 - engine - DEBUG - <UciProtocol (pid=6380)>: >> info time 716 nodes 604590
2019-09-08 21:39:36,327 - engine - DEBUG - <UciProtocol (pid=6380)>: >> bestmove g1f3 ponder c8g4
2019-09-08 21:39:36,327 - arena - INFO - elapse: 718
2019-09-08 21:39:36,327 - arena - INFO - time_left after search: 28237

The user can always disable logging when things are already running fine.

I am currently implementing Fischer Time Control.

...
  -tc TC TC             Time control. Usage: -tc < basetime > < inctime >
                        basetime and inctime are in milliseconds or ms.
                        Example: -tc 60000 100, That is 60s base and 100ms
                        increment.

In the log above I use a tc of -tc 30000 100 or 30s+100ms
arena - INFO - time_left after search: 28237
time_left before search: 28856
time left after search = 28856 + 100 - 718 = 28238, there is a 1ms discrepancy due to rounding.

So far so good, no time forfeit after 50 games are completed at -tc 30000 100
More test are needed.