Stockfish forfaits on time with fast games?

[stegemma]

I'm testing Satana tourney mode and I'm getting a strange behavior with Stockfish: it seems that in win position Stockfish and low time, Stockfish don't send the winning move.

Here's my log, maybe I'm missing some thing in interface to engine communication or Stockfish has some problem with this time control?



Here's the PGN:

[pgn]
[Event "blitz.5s.001"]
[Site "Norcia"]
[Date "2016-04-17 19:07:49"]
[Round "1"]
[White "satana.2.3.18"]
[Black "stockfish 7"]
[Result "*"]
[TimeControl "300000/5+100"]
[LigsRound "1:1:1"]
[LigsSoftware "Satana 2.3.18"]
[LigsTimeControl "300000:5000:100"]

1. d3 d5 2. a4 e5 3. Be3 Nc6 4. Nf3 Nf6 5. Nbd2 h6 6. a5 d4 7. Nxd4 exd4 8.
Bf4 Nd5 9. Bg3 Bb4 10. a6 bxa6 11. c4 dxc3 12. bxc3 Nxc3 13. Qb3 Ne4 14.
Bf4 Qf6 15. O-O-O Rb8 16. Nxe4 Qa1+ 17. Qb1 Ba3+ 18. Kc2 Rb2+ 19. Kc3
*
[/pgn]

Code: Select all

1	0	0	-	tourney blitz.5s.001
1	0	0	-	engine 1	satana.2.3.18	D:\A\LIGS\workspaces\vs\LIGS\exe\x64\Release\Satana.exe
1	0	0	-	engine 2	stockfish 7	D:\Arena\Engines\Stockfish\stockfish 7 x64 popcnt.exe
1	0	0	-	creating games
1	0	0	-	1 games created
1	0	0	-	          -   _
1	0	0	-	        [(|) (|)]       "IN MOTO L'OROLOGIO DEL BIANCO!"
1	0	0	-	_________________________
1	1	1	-	new match: 'satana.2.3.18' vs 'stockfish 7'
1	1	1	W	waiting for 'satana.2.3.18' initialization...
1	1	1	W	--->	xboard
1	1	1	W	--->	protover 2
1	1	1	W	--->	new
1	1	1	W	--->	post
1	1	1	B	waiting for 'stockfish 7' initialization...
1	1	1	B	--->	uci
1	1	1	B	<---	Stockfish 7 64 POPCNT by T. Romstad, M. Costalba, J. Kiiski, G. Linscott
1	1	1	B	<---	id name Stockfish 7 64 POPCNT
1	1	1	B	<---	id author T. Romstad, M. Costalba, J. Kiiski, G. Linscott
1	1	1	B	<---	option name Write Debug Log type check default false
1	1	1	B	<---	option name Contempt type spin default 0 min -100 max 100
1	1	1	B	<---	option name Threads type spin default 1 min 1 max 128
1	1	1	B	<---	option name Hash type spin default 16 min 1 max 1048576
1	1	1	B	<---	option name Clear Hash type button
1	1	1	B	<---	option name Ponder type check default false
1	1	1	B	<---	option name MultiPV type spin default 1 min 1 max 500
1	1	1	B	<---	option name Skill Level type spin default 20 min 0 max 20
1	1	1	B	<---	option name Move Overhead type spin default 30 min 0 max 5000
1	1	1	B	<---	option name Minimum Thinking Time type spin default 20 min 0 max 5000
1	1	1	B	<---	option name Slow Mover type spin default 84 min 10 max 1000
1	1	1	B	<---	option name nodestime type spin default 0 min 0 max 10000
1	1	1	B	<---	option name UCI_Chess960 type check default false
1	1	1	B	<---	option name SyzygyPath type string default <empty>
1	1	1	B	<---	option name SyzygyProbeDepth type spin default 1 min 1 max 100
1	1	1	B	<---	option name Syzygy50MoveRule type check default true
1	1	1	B	<---	option name SyzygyProbeLimit type spin default 6 min 0 max 6
1	1	1	B	<---	uciok
1	1	1	B	--->	ucinewgame
1	1	1	W	--->	time 500
1	1	1	W	--->	otim 500
1	1	1	W	--->	go
1	1	1	W	<---	# filling hash
1	1	1	W	<---	# I awakened the soul of Simple5
1	1	1	W	<---	# TT 2097152 entries - 128 MiB
1	1	1	W	<---	# Satana &#40;c&#41; 2012-2016 Stefano Gemma
1	1	1	W	<---	# zlib &#40;c&#41; 1995-2011 Mark Adler
1	1	1	W	<---	# xorshift &#40;c&#41; George Marsaglia
1	1	1	W	<---	# TT 2097152 entries - 128 MiB
1	1	1	W	<---	feature ping=1 setboard=1 done=1 san=0 usermove=1 time=1 draw=1 sigint=0 sigterm=0 reuse=1 analyze=0 myname="Satana 2.3.18" colors=0 ics=1 name=1 nps=0 debug=1 memory=1 smp=1
1	1	1	W	--->	ping 1
1	1	1	W	<---	# TT 2097152 entries - 128 MiB
1	1	1	W	<---	# moves 1/0 - time 123/5000 ms
1	1	1	W	<---	5 -8  12 107807 Pd2-d3
1	1	1	W	<---	# 127 ms 848 Knps, TT hits&#58; 9971 9.25%
1	1	1	W	<---	move d2d3
1	1	1	W	move d2d3
1	1	1	-	white 4949 ms | black 5000 ms
1	1	1	B	--->	position startpos moves d2d3 
1	1	1	B	--->	go wtime 4949 btime 5000 winc 100 binc 100
1	1	1	B	<---	info depth 1 seldepth 1 multipv 1 score cp 10 nodes 21 nps 21000 tbhits 0 time 1 pv e7e5
1	1	1	B	<---	info depth 2 seldepth 2 multipv 1 score cp 13 nodes 59 nps 59000 tbhits 0 time 1 pv e7e5 a2a3
1	1	1	B	<---	info depth 3 seldepth 3 multipv 1 score cp 10 nodes 104 nps 104000 tbhits 0 time 1 pv e7e5 c2c3 b7b6
1	1	1	B	<---	info depth 4 seldepth 4 multipv 1 score cp 7 nodes 401 nps 401000 tbhits 0 time 1 pv d7d5 d3d4 e7e6 e2e3
1	1	1	B	<---	info depth 5 seldepth 5 multipv 1 score cp 28 nodes 1715 nps 857500 tbhits 0 time 2 pv b8c6 d3d4 d7d5 g1f3 e7e6
1	1	1	B	<---	info depth 6 seldepth 6 multipv 1 score cp -10 nodes 3039 nps 1013000 tbhits 0 time 3 pv d7d5 e2e4 e7e5 b1c3 d5e4 c3e4
1	1	1	B	<---	info depth 7 seldepth 8 multipv 1 score cp -2 nodes 4116 nps 1372000 tbhits 0 time 3 pv d7d5 g1f3 b8c6 d3d4 e7e6 e2e3 a7a6
1	1	1	B	<---	info depth 8 seldepth 8 multipv 1 score cp 7 nodes 6639 nps 1327800 tbhits 0 time 5 pv d7d5 d3d4 e7e6 e2e3 g8f6 b1c3 b8c6 g1f3
1	1	1	B	<---	info depth 9 seldepth 9 multipv 1 score cp 3 nodes 16615 nps 1661500 tbhits 0 time 10 pv d7d5 c1f4 e7e5 f4e5 b8c6 g1f3 c6e5 f3e5 g8f6
1	1	1	B	<---	info depth 10 seldepth 11 multipv 1 score cp 6 nodes 39069 nps 1627875 tbhits 0 time 24 pv d7d5 e2e4 d5e4 b1c3 e4d3 d1d3 b8c6 d3d8 e8d8 g1f3 g8f6
1	1	1	B	<---	info depth 11 seldepth 17 multipv 1 score cp 14 nodes 95218 nps 1670491 tbhits 0 time 57 pv d7d5 e2e4 d5e4 b1c3 b8c6 c1e3 e4d3 d1d3 d8d3 f1d3 c8e6 e1c1 g8f6 g1f3 e8c8 h2h3
1	1	1	B	<---	info depth 12 seldepth 22 multipv 1 score cp 18 nodes 173560 nps 1668846 tbhits 0 time 104 pv d7d5 e2e4 d5e4 b1c3 b8c6 c1e3 e4d3 d1d3 d8d3 f1d3 c8e6 e1c1 c6b4 g1f3 e8c8 c1b1 b4d3 d1d3 d8d3 c2d3
1	1	1	B	<---	bestmove d7d5 ponder e2e4
1	1	1	B	move d7d5 ponder e2e4
1	1	1	-	white 4949 ms | black 4859 ms
1	1	1	W	--->	time 494
1	1	1	W	--->	otim 485
1	1	1	W	--->	d7d5
1	1	1	W	<---	pong 1
1	1	1	W	<---	# received move d7d5
1	1	1	W	<---	# moves 1/0 - time 122/4940 ms
1	1	1	W	<---	4 6  12 105925 Pa2-a4
1	1	1	W	<---	# 125 ms 847 Knps, TT hits&#58; 7741 7.31%
1	1	1	W	<---	move a2a4
1	1	1	W	move a2a4
1	1	1	-	white 4884 ms | black 4859 ms

&#91;...cut...&#93;

1	1	1	-	white 4323 ms | black 1744 ms
1	1	1	W	--->	time 432
1	1	1	W	--->	otim 174
1	1	1	W	--->	b4a3
1	1	1	W	<---	# received move b4a3
1	1	1	W	<---	# moves 1/0 - time 106/4320 ms
1	1	1	W	<---	3 -994  10 75412 Kc1-c2
1	1	1	W	<---	# 109 ms 691 Knps, TT hits&#58; 7221 9.58%
1	1	1	W	<---	move c1c2
1	1	1	W	move c1c2
1	1	1	-	white 4293 ms | black 1744 ms
1	1	1	B	--->	position startpos moves d2d3 d7d5 a2a4 e7e5 c1e3 b8c6 g1f3 g8f6 b1d2 h7h6 a4a5 d5d4 f3d4 e5d4 e3f4 f6d5 f4g3 f8b4 a5a6 b7a6 c2c4 d4c3 b2c3 d5c3 d1b3 c3e4 g3f4 d8f6 e1c1 a8b8 d2e4 f6a1 b3b1 b4a3 c1c2 
1	1	1	B	--->	go wtime 4293 btime 1744 winc 100 binc 100
1	1	1	B	<---	info depth 1 seldepth 2 multipv 1 score cp 2049 nodes 130 nps 65000 tbhits 0 time 2 pv b8b2 c2c3 b2b1 c3c2
1	1	1	B	<---	info depth 2 seldepth 4 multipv 1 score mate 3 nodes 320 nps 160000 tbhits 0 time 2 pv b8b2 c2c3 a3b4 c3c4
1	1	1	B	<---	info depth 3 seldepth 6 multipv 1 score mate 3 nodes 431 nps 215500 tbhits 0 time 2 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 4 seldepth 6 multipv 1 score mate 3 nodes 511 nps 255500 tbhits 0 time 2 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 5 seldepth 6 multipv 1 score mate 3 nodes 591 nps 295500 tbhits 0 time 2 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 6 seldepth 6 multipv 1 score mate 3 nodes 678 nps 339000 tbhits 0 time 2 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 7 seldepth 6 multipv 1 score mate 3 nodes 766 nps 383000 tbhits 0 time 2 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 8 seldepth 6 multipv 1 score mate 3 nodes 897 nps 448500 tbhits 0 time 2 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 9 seldepth 6 multipv 1 score mate 3 nodes 1015 nps 507500 tbhits 0 time 2 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 10 seldepth 6 multipv 1 score mate 3 nodes 1259 nps 629500 tbhits 0 time 2 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 11 seldepth 6 multipv 1 score mate 3 nodes 1702 nps 851000 tbhits 0 time 2 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 12 seldepth 6 multipv 1 score mate 3 nodes 2652 nps 884000 tbhits 0 time 3 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 13 seldepth 6 multipv 1 score mate 3 nodes 3505 nps 1168333 tbhits 0 time 3 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 14 seldepth 6 multipv 1 score mate 3 nodes 4984 nps 1661333 tbhits 0 time 3 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 15 seldepth 6 multipv 1 score mate 3 nodes 6222 nps 1555500 tbhits 0 time 4 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 16 seldepth 6 multipv 1 score mate 3 nodes 6692 nps 1673000 tbhits 0 time 4 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 17 seldepth 6 multipv 1 score mate 3 nodes 7678 nps 1919500 tbhits 0 time 4 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 18 seldepth 6 multipv 1 score mate 3 nodes 8664 nps 2166000 tbhits 0 time 4 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 19 seldepth 6 multipv 1 score mate 3 nodes 9786 nps 1957200 tbhits 0 time 5 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 20 seldepth 6 multipv 1 score mate 3 nodes 10583 nps 2116600 tbhits 0 time 5 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 21 seldepth 6 multipv 1 score mate 3 nodes 11933 nps 2386600 tbhits 0 time 5 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 22 seldepth 6 multipv 1 score mate 3 nodes 13535 nps 2255833 tbhits 0 time 6 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 23 seldepth 6 multipv 1 score mate 3 nodes 15521 nps 2586833 tbhits 0 time 6 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 24 seldepth 6 multipv 1 score mate 3 nodes 16682 nps 2383142 tbhits 0 time 7 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 25 seldepth 6 multipv 1 score mate 3 nodes 18453 nps 2636142 tbhits 0 time 7 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 26 seldepth 6 multipv 1 score mate 3 nodes 20747 nps 2593375 tbhits 0 time 8 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 27 seldepth 6 multipv 1 score mate 3 nodes 23810 nps 2645555 tbhits 0 time 9 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 28 seldepth 6 multipv 1 score mate 3 nodes 26295 nps 2921666 tbhits 0 time 9 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 29 seldepth 6 multipv 1 score mate 3 nodes 29829 nps 2711727 tbhits 0 time 11 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 30 seldepth 6 multipv 1 score mate 3 nodes 36239 nps 2787615 tbhits 0 time 13 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 31 seldepth 6 multipv 1 score mate 3 nodes 41764 nps 2784266 tbhits 0 time 15 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 32 seldepth 6 multipv 1 score mate 3 nodes 46034 nps 2877125 tbhits 0 time 16 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 33 seldepth 6 multipv 1 score mate 3 nodes 52383 nps 2910166 tbhits 0 time 18 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 34 seldepth 6 multipv 1 score mate 3 nodes 58324 nps 2916200 tbhits 0 time 20 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 35 seldepth 6 multipv 1 score mate 3 nodes 62373 nps 2970142 tbhits 0 time 21 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 36 seldepth 6 multipv 1 score mate 3 nodes 65478 nps 2976272 tbhits 0 time 22 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 37 seldepth 6 multipv 1 score mate 3 nodes 70468 nps 3063826 tbhits 0 time 23 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 38 seldepth 6 multipv 1 score mate 3 nodes 75912 nps 3163000 tbhits 0 time 24 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 39 seldepth 6 multipv 1 score mate 3 nodes 80050 nps 3202000 tbhits 0 time 25 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 40 seldepth 6 multipv 1 score mate 3 nodes 82638 nps 3305520 tbhits 0 time 25 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 41 seldepth 6 multipv 1 score mate 3 nodes 87439 nps 3363038 tbhits 0 time 26 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 42 seldepth 6 multipv 1 score mate 3 nodes 93012 nps 3444888 tbhits 0 time 27 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 43 seldepth 6 multipv 1 score mate 3 nodes 97456 nps 3480571 tbhits 0 time 28 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 44 seldepth 6 multipv 1 score mate 3 nodes 99979 nps 3570678 tbhits 0 time 28 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 45 seldepth 6 multipv 1 score mate 3 nodes 104706 nps 3610551 tbhits 0 time 29 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 46 seldepth 6 multipv 1 score mate 3 nodes 110282 nps 3557483 tbhits 0 time 31 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 47 seldepth 6 multipv 1 score mate 3 nodes 114965 nps 3592656 tbhits 0 time 32 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 48 seldepth 6 multipv 1 score mate 3 nodes 117763 nps 3680093 tbhits 0 time 32 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 49 seldepth 6 multipv 1 score mate 3 nodes 122060 nps 3698787 tbhits 0 time 33 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 50 seldepth 6 multipv 1 score mate 3 nodes 127466 nps 3749000 tbhits 0 time 34 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 51 seldepth 6 multipv 1 score mate 3 nodes 132338 nps 3781085 tbhits 0 time 35 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 52 seldepth 6 multipv 1 score mate 3 nodes 135102 nps 3752833 tbhits 0 time 36 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 53 seldepth 6 multipv 1 score mate 3 nodes 139648 nps 3674947 tbhits 0 time 38 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 54 seldepth 6 multipv 1 score mate 3 nodes 144390 nps 3702307 tbhits 0 time 39 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 55 seldepth 6 multipv 1 score mate 3 nodes 147619 nps 3690475 tbhits 0 time 40 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 56 seldepth 6 multipv 1 score mate 3 nodes 151526 nps 3695756 tbhits 0 time 41 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 57 seldepth 6 multipv 1 score mate 3 nodes 157096 nps 3740380 tbhits 0 time 42 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 58 seldepth 6 multipv 1 score mate 3 nodes 161960 nps 3766511 tbhits 0 time 43 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 59 seldepth 6 multipv 1 score mate 3 nodes 165319 nps 3757250 tbhits 0 time 44 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 60 seldepth 6 multipv 1 score mate 3 nodes 169133 nps 3758511 tbhits 0 time 45 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 61 seldepth 6 multipv 1 score mate 3 nodes 174855 nps 3801195 tbhits 0 time 46 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 62 seldepth 6 multipv 1 score mate 3 nodes 179901 nps 3827680 tbhits 0 time 47 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 63 seldepth 6 multipv 1 score mate 3 nodes 183449 nps 3821854 tbhits 0 time 48 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 64 seldepth 6 multipv 1 score mate 3 nodes 187058 nps 3817510 tbhits 0 time 49 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 65 seldepth 6 multipv 1 score mate 3 nodes 192864 nps 3857280 tbhits 0 time 50 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 66 seldepth 6 multipv 1 score mate 3 nodes 197840 nps 3804615 tbhits 0 time 52 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 67 seldepth 6 multipv 1 score mate 3 nodes 201498 nps 3801849 tbhits 0 time 53 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 68 seldepth 6 multipv 1 score mate 3 nodes 205139 nps 3798870 tbhits 0 time 54 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 69 seldepth 6 multipv 1 score mate 3 nodes 210920 nps 3834909 tbhits 0 time 55 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 70 seldepth 6 multipv 1 score mate 3 nodes 216045 nps 3857946 tbhits 0 time 56 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 71 seldepth 6 multipv 1 score mate 3 nodes 219370 nps 3917321 tbhits 0 time 56 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 72 seldepth 6 multipv 1 score mate 3 nodes 223279 nps 3917175 tbhits 0 time 57 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 73 seldepth 6 multipv 1 score mate 3 nodes 228313 nps 3936431 tbhits 0 time 58 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 74 seldepth 6 multipv 1 score mate 3 nodes 231981 nps 3999672 tbhits 0 time 58 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 75 seldepth 6 multipv 1 score mate 3 nodes 235662 nps 3994271 tbhits 0 time 59 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 76 seldepth 6 multipv 1 score mate 3 nodes 241495 nps 4024916 tbhits 0 time 60 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 77 seldepth 6 multipv 1 score mate 3 nodes 246496 nps 4108266 tbhits 0 time 60 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 78 seldepth 6 multipv 1 score mate 3 nodes 250147 nps 4100770 tbhits 0 time 61 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 79 seldepth 6 multipv 1 score mate 3 nodes 253814 nps 4093774 tbhits 0 time 62 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 80 seldepth 6 multipv 1 score mate 3 nodes 259676 nps 4188322 tbhits 0 time 62 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 81 seldepth 6 multipv 1 score mate 3 nodes 264692 nps 4201460 tbhits 0 time 63 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 82 seldepth 6 multipv 1 score mate 3 nodes 268267 nps 4191671 tbhits 0 time 64 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 83 seldepth 6 multipv 1 score mate 3 nodes 271898 nps 4248406 tbhits 0 time 64 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 84 seldepth 6 multipv 1 score mate 3 nodes 277830 nps 4274307 tbhits 0 time 65 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 85 seldepth 6 multipv 1 score mate 3 nodes 282922 nps 4286696 tbhits 0 time 66 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 86 seldepth 6 multipv 1 score mate 3 nodes 286596 nps 4277552 tbhits 0 time 67 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 87 seldepth 6 multipv 1 score mate 3 nodes 290129 nps 4330283 tbhits 0 time 67 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 88 seldepth 6 multipv 1 score mate 3 nodes 295866 nps 4350970 tbhits 0 time 68 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 89 seldepth 6 multipv 1 score mate 3 nodes 300818 nps 4359681 tbhits 0 time 69 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 90 seldepth 6 multipv 1 score mate 3 nodes 304429 nps 4412014 tbhits 0 time 69 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 91 seldepth 6 multipv 1 score mate 3 nodes 308004 nps 4400057 tbhits 0 time 70 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 92 seldepth 6 multipv 1 score mate 3 nodes 313699 nps 4418295 tbhits 0 time 71 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 93 seldepth 6 multipv 1 score mate 3 nodes 318866 nps 4491070 tbhits 0 time 71 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 94 seldepth 6 multipv 1 score mate 3 nodes 322288 nps 4476222 tbhits 0 time 72 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 95 seldepth 6 multipv 1 score mate 3 nodes 326195 nps 4530486 tbhits 0 time 72 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 96 seldepth 6 multipv 1 score mate 3 nodes 331289 nps 4538205 tbhits 0 time 73 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 97 seldepth 6 multipv 1 score mate 3 nodes 334898 nps 4525648 tbhits 0 time 74 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 98 seldepth 6 multipv 1 score mate 3 nodes 338523 nps 4574635 tbhits 0 time 74 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 99 seldepth 6 multipv 1 score mate 3 nodes 344393 nps 4531486 tbhits 0 time 76 pv b8b2 c2c3 a3b4 c3c4 c8e6
1	1	1	B	<---	bestmove b8b2 ponder c2c3
1	1	1	B	move b8b2 ponder c2c3
1	1	1	-	white 4293 ms | black 694 ms
1	1	1	W	--->	time 429
1	1	1	W	--->	otim 69
1	1	1	W	--->	b8b2
1	1	1	W	<---	# received move b8b2
1	1	1	W	<---	# moves 1/0 - time 106/4290 ms
1	1	1	W	<---	127 -10000  9 78542 Kc2-c3
1	1	1	W	<---	# 102 ms 770 Knps, TT hits&#58; 7447 9.48%
1	1	1	W	<---	move c2c3
1	1	1	W	move c2c3
1	1	1	-	white 4270 ms | black 694 ms
1	1	1	B	--->	position startpos moves d2d3 d7d5 a2a4 e7e5 c1e3 b8c6 g1f3 g8f6 b1d2 h7h6 a4a5 d5d4 f3d4 e5d4 e3f4 f6d5 f4g3 f8b4 a5a6 b7a6 c2c4 d4c3 b2c3 d5c3 d1b3 c3e4 g3f4 d8f6 e1c1 a8b8 d2e4 f6a1 b3b1 b4a3 c1c2 b8b2 c2c3 
1	1	1	B	--->	go wtime 4270 btime 694 winc 100 binc 100
1	1	1	B	<---	info depth 1 seldepth 2 multipv 1 score mate 2 nodes 78 nps 78000 tbhits 0 time 1 pv a3b4 c3c4
1	1	1	B	<---	info depth 2 seldepth 4 multipv 1 score mate 2 nodes 129 nps 129000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 3 seldepth 4 multipv 1 score mate 2 nodes 182 nps 182000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 4 seldepth 4 multipv 1 score mate 2 nodes 233 nps 233000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 5 seldepth 4 multipv 1 score mate 2 nodes 284 nps 284000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 6 seldepth 4 multipv 1 score mate 2 nodes 335 nps 335000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 7 seldepth 4 multipv 1 score mate 2 nodes 386 nps 386000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 8 seldepth 4 multipv 1 score mate 2 nodes 437 nps 437000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 9 seldepth 4 multipv 1 score mate 2 nodes 488 nps 488000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 10 seldepth 4 multipv 1 score mate 2 nodes 539 nps 539000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 11 seldepth 4 multipv 1 score mate 2 nodes 590 nps 590000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 12 seldepth 4 multipv 1 score mate 2 nodes 641 nps 641000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 13 seldepth 4 multipv 1 score mate 2 nodes 692 nps 692000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 14 seldepth 4 multipv 1 score mate 2 nodes 745 nps 745000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 15 seldepth 4 multipv 1 score mate 2 nodes 797 nps 797000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 16 seldepth 4 multipv 1 score mate 2 nodes 848 nps 848000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 17 seldepth 4 multipv 1 score mate 2 nodes 900 nps 900000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 18 seldepth 4 multipv 1 score mate 2 nodes 952 nps 952000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 19 seldepth 4 multipv 1 score mate 2 nodes 1004 nps 1004000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 20 seldepth 4 multipv 1 score mate 2 nodes 1055 nps 1055000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 21 seldepth 4 multipv 1 score mate 2 nodes 1107 nps 1107000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 22 seldepth 4 multipv 1 score mate 2 nodes 1159 nps 1159000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 23 seldepth 4 multipv 1 score mate 2 nodes 1211 nps 1211000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 24 seldepth 4 multipv 1 score mate 2 nodes 1262 nps 1262000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 25 seldepth 4 multipv 1 score mate 2 nodes 1314 nps 1314000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 26 seldepth 4 multipv 1 score mate 2 nodes 1366 nps 1366000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 27 seldepth 4 multipv 1 score mate 2 nodes 1418 nps 1418000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 28 seldepth 4 multipv 1 score mate 2 nodes 1469 nps 1469000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 29 seldepth 4 multipv 1 score mate 2 nodes 1521 nps 1521000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 30 seldepth 4 multipv 1 score mate 2 nodes 1573 nps 1573000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 31 seldepth 4 multipv 1 score mate 2 nodes 1624 nps 1624000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 32 seldepth 4 multipv 1 score mate 2 nodes 1675 nps 1675000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 33 seldepth 4 multipv 1 score mate 2 nodes 1727 nps 1727000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 34 seldepth 4 multipv 1 score mate 2 nodes 1779 nps 1779000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 35 seldepth 4 multipv 1 score mate 2 nodes 1831 nps 1831000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 36 seldepth 4 multipv 1 score mate 2 nodes 1882 nps 1882000 tbhits 0 time 1 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 37 seldepth 4 multipv 1 score mate 2 nodes 1934 nps 967000 tbhits 0 time 2 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 38 seldepth 4 multipv 1 score mate 2 nodes 1986 nps 993000 tbhits 0 time 2 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 39 seldepth 4 multipv 1 score mate 2 nodes 2038 nps 1019000 tbhits 0 time 2 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 40 seldepth 4 multipv 1 score mate 2 nodes 2089 nps 1044500 tbhits 0 time 2 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 41 seldepth 4 multipv 1 score mate 2 nodes 2141 nps 1070500 tbhits 0 time 2 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 42 seldepth 4 multipv 1 score mate 2 nodes 2193 nps 1096500 tbhits 0 time 2 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 43 seldepth 4 multipv 1 score mate 2 nodes 2245 nps 1122500 tbhits 0 time 2 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 44 seldepth 4 multipv 1 score mate 2 nodes 2296 nps 1148000 tbhits 0 time 2 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 45 seldepth 4 multipv 1 score mate 2 nodes 2348 nps 1174000 tbhits 0 time 2 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 46 seldepth 4 multipv 1 score mate 2 nodes 2400 nps 1200000 tbhits 0 time 2 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 47 seldepth 4 multipv 1 score mate 2 nodes 2452 nps 1226000 tbhits 0 time 2 pv a3b4 c3c4 c8e6
1	1	1	B	<---	info depth 48 seldepth 4 multipv 1 score mate 2 nodes 2503 nps 1251500 tbhits 0 time 2 pv a3b4 c3c4 c8e6
1	1	1	B	stockfish 7 forfaits on time
1	1	1	-	'satana.2.3.18' result 2 score 2
1	1	1	-	'stockfish 7' result 0 score 0
1	1	1	W	--->	quit
1	2	0	-	----------------- tournament has finished
1	2	0	-	satana.2.3.18&#58; 2
1	2	0	-	stockfish 7&#58; 0
1	2	0	-	-----------------
1	2	1	B	--->	quit

[Joerg Oster]

I never experienced time losses by Stockfish, even when playing with a much shorter tc like 1"+0.03" (single mode).

Why does the tourney manager give a time forfeit?
SF has been told to have 694 msec available ...

Code: Select all

go wtime 4270 btime 694 winc 100 binc 100

... and only used 2 msec so far.

Code: Select all

info depth 48 seldepth 4 multipv 1 score mate 2 nodes 2503 nps 1251500 tbhits 0 time 2 pv a3b4 c3c4 c8e6

Looks strange.

[stegemma]

I never experienced time losses by Stockfish, even when playing with a much shorter tc like 1"+0.03" (single mode).

Why does the tourney manager give a time forfeit?
SF has been told to have 694 msec available ...

Code: Select all

go wtime 4270 btime 694 winc 100 binc 100

... and only used 2 msec so far.

Code: Select all

info depth 48 seldepth 4 multipv 1 score mate 2 nodes 2503 nps 1251500 tbhits 0 time 2 pv a3b4 c3c4 c8e6

Looks strange.

So there must be some problem in my tourney manager. Maybe it don't poll the engine enough fast or something similar.

Thanks for your support.

[hgm]

All the output shows is that SF used 2 msec the last time it said something. It could have been hanging silently for 700 msec after that.

[stegemma]

All the output shows is that SF used 2 msec the last time it said something. It could have been hanging silently for 700 msec after that.

In fact I'm adding right now a little wait after the forfait and then the pop of any residual message from the engine.

I'll let you know...

[stegemma]

Maybe I've found the problem:

Code: Select all

1	17976	1	1	B	<---	info depth 6 seldepth 4 multipv 1 score mate 2 nodes 413 nps 206500 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	17991	1	1	B	<---	info depth 7 seldepth 4 multipv 1 score mate 2 nodes 482 nps 241000 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18014	1	1	B	stockfish 7 forfaits on time
1	18019	1	1	B	testing for missing messages for 2 seconds...
1	18045	1	1	B	<---	info depth 8 seldepth 4 multipv 1 score mate 2 nodes 558 nps 279000 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18061	1	1	B	<---	info depth 9 seldepth 4 multipv 1 score mate 2 nodes 626 nps 313000 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18077	1	1	B	<---	info depth 10 seldepth 4 multipv 1 score mate 2 nodes 703 nps 351500 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18099	1	1	B	<---	info depth 11 seldepth 4 multipv 1 score mate 2 nodes 817 nps 408500 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18114	1	1	B	<---	info depth 12 seldepth 4 multipv 1 score mate 2 nodes 942 nps 471000 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18146	1	1	B	<---	info depth 13 seldepth 4 multipv 1 score mate 2 nodes 1046 nps 523000 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18161	1	1	B	<---	info depth 14 seldepth 4 multipv 1 score mate 2 nodes 1191 nps 595500 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18177	1	1	B	<---	info depth 15 seldepth 4 multipv 1 score mate 2 nodes 1301 nps 650500 tbhits 0 time 2 pv e8g8 g2f3 e6h3

&#91;...cut...&#93;

1	20063	2	1	B	<---	info depth 115 seldepth 4 multipv 1 score mate 2 nodes 12418 nps 388062 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20078	2	1	B	<---	info depth 116 seldepth 4 multipv 1 score mate 2 nodes 12533 nps 391656 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20094	2	1	B	<---	info depth 117 seldepth 4 multipv 1 score mate 2 nodes 12631 nps 394718 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20116	2	1	B	<---	info depth 118 seldepth 4 multipv 1 score mate 2 nodes 12751 nps 398468 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20132	2	1	B	<---	info depth 119 seldepth 4 multipv 1 score mate 2 nodes 12872 nps 402250 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20148	2	1	B	<---	info depth 120 seldepth 4 multipv 1 score mate 2 nodes 12987 nps 405843 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20163	2	1	B	<---	info depth 121 seldepth 4 multipv 1 score mate 2 nodes 13085 nps 408906 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20179	2	1	B	<---	info depth 122 seldepth 4 multipv 1 score mate 2 nodes 13205 nps 412656 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20199	2	1	B	<---	info depth 123 seldepth 4 multipv 1 score mate 2 nodes 13326 nps 416437 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20217	2	1	B	<---	info depth 124 seldepth 4 multipv 1 score mate 2 nodes 13441 nps 420031 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20232	2	1	B	<---	info depth 125 seldepth 4 multipv 1 score mate 2 nodes 13539 nps 423093 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20248	2	1	B	<---	info depth 126 seldepth 4 multipv 1 score mate 2 nodes 13659 nps 426843 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20263	2	1	B	<---	info depth 127 seldepth 4 multipv 1 score mate 2 nodes 13780 nps 430625 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20279	2	1	B	<---	bestmove e8g8 ponder g2f3
1	20285	2	1	B	found after 2271 ms&#58;	move e8g8 ponder g2f3
1	39127	2	1	-	'satana.2.3.18' result 2 score 2
1	39131	2	1	-	'stockfish 7' result 0 score 0
1	39136	2	1	W	--->	quit
1	42151	2	1	B	--->	quit

My manager maybe lose time to pop/display/store "info" messages and when time has finished there are still messages to pop. Stockfish in effect seems to send response in just 32 ms. It could be not so clear, but all "info" log registered after "stockfish 7 forfaits on time" are stored by the engine interface object, that is a separate thread form the "game thread". The last receive the "move e8g8" after 2271ms just because the buffer is still full of "info".

Wy SF needs to send such amount of info for a mate in 2 I really don't know

[MikeB]

I have seen SF lose on time , but not the way it's losing on time with you. In fact it is by far the strongest engine at micro bullet tc 2 sec with .1 sec increments or faster.

[bob]

Maybe I've found the problem:

Code: Select all

1	17976	1	1	B	<---	info depth 6 seldepth 4 multipv 1 score mate 2 nodes 413 nps 206500 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	17991	1	1	B	<---	info depth 7 seldepth 4 multipv 1 score mate 2 nodes 482 nps 241000 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18014	1	1	B	stockfish 7 forfaits on time
1	18019	1	1	B	testing for missing messages for 2 seconds...
1	18045	1	1	B	<---	info depth 8 seldepth 4 multipv 1 score mate 2 nodes 558 nps 279000 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18061	1	1	B	<---	info depth 9 seldepth 4 multipv 1 score mate 2 nodes 626 nps 313000 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18077	1	1	B	<---	info depth 10 seldepth 4 multipv 1 score mate 2 nodes 703 nps 351500 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18099	1	1	B	<---	info depth 11 seldepth 4 multipv 1 score mate 2 nodes 817 nps 408500 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18114	1	1	B	<---	info depth 12 seldepth 4 multipv 1 score mate 2 nodes 942 nps 471000 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18146	1	1	B	<---	info depth 13 seldepth 4 multipv 1 score mate 2 nodes 1046 nps 523000 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18161	1	1	B	<---	info depth 14 seldepth 4 multipv 1 score mate 2 nodes 1191 nps 595500 tbhits 0 time 2 pv e8g8 g2f3 e6h3
1	18177	1	1	B	<---	info depth 15 seldepth 4 multipv 1 score mate 2 nodes 1301 nps 650500 tbhits 0 time 2 pv e8g8 g2f3 e6h3

&#91;...cut...&#93;

1	20063	2	1	B	<---	info depth 115 seldepth 4 multipv 1 score mate 2 nodes 12418 nps 388062 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20078	2	1	B	<---	info depth 116 seldepth 4 multipv 1 score mate 2 nodes 12533 nps 391656 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20094	2	1	B	<---	info depth 117 seldepth 4 multipv 1 score mate 2 nodes 12631 nps 394718 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20116	2	1	B	<---	info depth 118 seldepth 4 multipv 1 score mate 2 nodes 12751 nps 398468 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20132	2	1	B	<---	info depth 119 seldepth 4 multipv 1 score mate 2 nodes 12872 nps 402250 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20148	2	1	B	<---	info depth 120 seldepth 4 multipv 1 score mate 2 nodes 12987 nps 405843 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20163	2	1	B	<---	info depth 121 seldepth 4 multipv 1 score mate 2 nodes 13085 nps 408906 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20179	2	1	B	<---	info depth 122 seldepth 4 multipv 1 score mate 2 nodes 13205 nps 412656 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20199	2	1	B	<---	info depth 123 seldepth 4 multipv 1 score mate 2 nodes 13326 nps 416437 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20217	2	1	B	<---	info depth 124 seldepth 4 multipv 1 score mate 2 nodes 13441 nps 420031 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20232	2	1	B	<---	info depth 125 seldepth 4 multipv 1 score mate 2 nodes 13539 nps 423093 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20248	2	1	B	<---	info depth 126 seldepth 4 multipv 1 score mate 2 nodes 13659 nps 426843 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20263	2	1	B	<---	info depth 127 seldepth 4 multipv 1 score mate 2 nodes 13780 nps 430625 tbhits 0 time 32 pv e8g8 g2f3 e6h3
1	20279	2	1	B	<---	bestmove e8g8 ponder g2f3
1	20285	2	1	B	found after 2271 ms&#58;	move e8g8 ponder g2f3
1	39127	2	1	-	'satana.2.3.18' result 2 score 2
1	39131	2	1	-	'stockfish 7' result 0 score 0
1	39136	2	1	W	--->	quit
1	42151	2	1	B	--->	quit

My manager maybe lose time to pop/display/store "info" messages and when time has finished there are still messages to pop. Stockfish in effect seems to send response in just 32 ms. It could be not so clear, but all "info" log registered after "stockfish 7 forfaits on time" are stored by the engine interface object, that is a separate thread form the "game thread". The last receive the "move e8g8" after 2271ms just because the buffer is still full of "info".

Wy SF needs to send such amount of info for a mate in 2 I really don't know

There are several such "bad actors" that send WAY too much output. And too much output from one side can interfere with input from the other side.

[stegemma]

[...]
There are several such "bad actors" that send WAY too much output. And too much output from one side can interfere with input from the other side.

I've partially solved saving in memory logs for any game and then storing the file just at the end (Satana never crashes... or almost this I hope).

Still it has no sense to search up to ply 100 and over for a mate in 2/3 moves and maybe I must penalize Stockfish and similar softwares for this.