Deep analysis problems ?

[allorder]

Hi, Every time the engine goes in deep analysis I got some errors.

Apr 05 18:26:27 tux python[2384]: ><> 2: ENGINE: 16394 >> info depth 20 seldepth 35 multipv 1 score cp -19 nodes 3116525 nps 6479261 tbhits 0 time 481 pv d1f1 f4d4 f1f6 d4d2 b2c3 d2d5 b3c4 d5c5 c3d4 c5c4 d4e5 g5g4 f6f7 h7h5 h3g4 c4g4 g1c1 c7c6 f7c7 g4g7 e5d6 h5h4 c7g7 g8g7 c1h1 g7f6 h1h4 Apr 05 18:26:27 tux python[2384]: Thread-1: ERROR: Could not send progress report. Continuing. Apr 05 18:26:27 tux python[2384]: Traceback (most recent call last): Apr 05 18:26:27 tux python[2384]: File "/home/allorder/.local/lib/python2.7/site-packages/fishnet.py", line 563, in run Apr 05 18:26:27 tux python[2384]: timeout=HTTP_TIMEOUT) Apr 05 18:26:27 tux python[2384]: File "/home/allorder/.local/lib/python2.7/site-packages/requests/sessions.py", line 555, in post Apr 05 18:26:27 tux python[2384]: return self.request('POST', url, data=data, json=json, kwargs) Apr 05 18:26:27 tux python[2384]: File "/home/allorder/.local/lib/python2.7/site-packages/requests/sessions.py", line 508, in request Apr 05 18:26:27 tux python[2384]: resp = self.send(prep, send_kwargs) Apr 05 18:26:27 tux python[2384]: File "/home/allorder/.local/lib/python2.7/site-packages/requests/sessions.py", line 618, in send Apr 05 18:26:27 tux python[2384]: r = adapter.send(request, **kwargs) Apr 05 18:26:27 tux python[2384]: File "/home/allorder/.local/lib/python2.7/site-packages/requests/adapters.py", line 490, in send Apr 05 18:26:27 tux python[2384]: raise ConnectionError(err, request=request) Apr 05 18:26:27 tux python[2384]: ConnectionError: ('Connection aborted.', BadStatusLine("''",)) Apr 05 18:26:35 tux python[2384]: [fishnet v1.15.9] Analyzed 762888 positions, crunched 2977540 million nodes Apr 05 18:27:03 tux python[2384]: ><> 2: https://lichess.org/4l7MKFqP took 61.7s (0.53s per position) Apr 05 18:27:35 tux python[2384]: [fishnet v1.15.9] Analyzed 763007 positions, crunched 2977973 million nodes Apr 05 18:28:06 tux python[2384]: ><> 1: https://lichess.org/Pov1VwHp took 64.6s (0.73s per position) Apr 05 18:28:10 tux python[2384]: ><> 2: https://lichess.org/RRqhDYfg took 62.4s (1.04s per position) Apr 05 18:28:35 tux python[2384]: [fishnet v1.15.9] Analyzed 763069 positions, crunched 2978221 million nodes Apr 05 18:29:29 tux python[2384]: ><> 1: https://lichess.org/LSwIo7lv took 40.9s (0.95s per position) Apr 05 18:29:35 tux python[2384]: [fishnet v1.15.9] Analyzed 763186 positions, crunched 2978682 million nodes

[niklasf]

From the log it looks like it also finished some games without any problems, so it might just be a temporary network issue or lichess.org was not reachable while it was updating. Is this very frequent?

[allorder]

Yes, every time when in deep analysis. No problem with normal game analysis. I have the same behavior on another box with different ISP.

[allorder]

Apr 06 08:55:20 kknd python[23526]: [fishnet v1.15.9] Analyzed 3208 positions, crunched 12569 million nodes Apr 06 08:55:31 kknd python[23526]: ><> 1: https://lichess.org/Yuve1kyZ took 13.6s (0.45s per position) Apr 06 08:56:20 kknd python[23526]: [fishnet v1.15.9] Analyzed 3231 positions, crunched 12661 million nodes Apr 06 08:57:09 kknd python[23526]: ><> 1: https://lichess.org/uh7JbRpn took 32.1s (0.56s per position) Apr 06 08:57:20 kknd python[23526]: [fishnet v1.15.9] Analyzed 3311 positions, crunched 12982 million nodes Apr 06 08:57:35 kknd python[23526]: ><> 1: https://lichess.org/SZZGDyy9 took 25.6s (0.51s per position) Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 4 seldepth 4 multipv 1 score cp 616 nodes 611 nps 611000 tbhits 0 time 1 pv c8a8 a2a4 f7f5 a4a5 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 5 seldepth 5 multipv 1 score cp 613 nodes 972 nps 972000 tbhits 0 time 1 pv f7f5 g2g3 c8a8 b3b4 g7g5 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 6 seldepth 6 multipv 1 score cp 613 nodes 1508 nps 1508000 tbhits 0 time 1 pv f7f5 g2g3 c8a8 b3b4 g7g5 a2a3 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 7 seldepth 7 multipv 1 score cp 613 nodes 1931 nps 1931000 tbhits 0 time 1 pv f7f5 g2g3 c8a8 b3b4 g7g5 a2a3 c8c7 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 8 seldepth 9 multipv 1 score cp 613 nodes 2752 nps 2752000 tbhits 0 time 1 pv f7f5 g2g3 c8a8 g1f2 e3g4 f2g2 h7h5 h2h3 g4e5 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 9 seldepth 10 multipv 1 score cp 614 nodes 4493 nps 4493000 tbhits 0 time 1 pv f7f5 a2a3 c8a8 g1f2 f5f4 g2g3 g7g5 g3f4 g5f4 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 10 seldepth 12 multipv 1 score cp 606 nodes 7123 nps 3561500 tbhits 0 time 2 pv f7f5 a2a3 c8a8 g1f2 f5f4 g2g3 g7g5 b1e4 e8h5 g3f4 g5f4 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 11 seldepth 16 multipv 1 score cp 616 nodes 15060 nps 7530000 tbhits 0 time 2 pv f7f5 g2g3 c8a8 a2a4 e6e5 g1f2 f5f4 g3f4 e5f4 e1g1 g7g6 b1e4 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 12 seldepth 21 multipv 1 score cp 616 nodes 35644 nps 8911000 tbhits 0 time 4 pv f7f5 a2a4 c8a8 g1f2 f5f4 g2g3 e6e5 g3f4 e5f4 e1g1 g7g6 b1e4 d8d2 f2f3 h8f8 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 13 seldepth 20 multipv 1 score cp 605 nodes 58935 nps 8419285 tbhits 0 time 7 pv f7f5 a2a4 c8a8 g1f2 f5f4 g2g3 e6e5 g3f4 e5f4 e1g1 g7g6 a4a5 e8f7 a5a6 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 14 seldepth 23 multipv 1 score cp 606 nodes 90571 nps 9057100 tbhits 0 time 10 pv f7f5 a2a4 c8a8 g1f2 f5f4 g2g3 g7g5 h2h4 g5h4 g3f4 e3d1 f2f1 h8g8 b1h7 d1e3 f1f2 g8g3 h7d3 e3g4 f2f1 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 15 seldepth 26 multipv 1 score cp 613 nodes 205821 nps 9355500 tbhits 0 time 22 pv f7f5 a2a4 c8a8 a4a5 e6e5 g1f2 e3g4 f2g1 e5e4 h2h3 g4e3 g1f2 e3d5 a5a6 e8f7 a6b7 c8b7 g2g4 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 16 seldepth 23 multipv 1 score cp 613 nodes 298032 nps 9313500 tbhits 0 time 32 pv f7f5 a2a4 c8a8 a4a5 e6e5 g1f2 e3g4 f2g1 e5e4 h2h3 g4e3 g1f2 e3d5 a5a6 e8f7 a6b7 c8b7 g2g4 f5g4 h3g4 f7g6 a1a4 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 17 seldepth 25 multipv 1 score cp 624 nodes 1420237 nps 9343664 tbhits 0 time 152 pv f7f5 a2a4 c8a8 a4a5 e6e5 g1f2 e3g4 f2g1 e5e4 h2h3 g4e5 a5a6 e8g6 g1f2 g6f7 e1f1 f7e6 a6b7 c8b7 a1a4 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 18 seldepth 32 multipv 1 score cp 600 nodes 2698812 nps 9179632 tbhits 0 time 294 pv f7f5 a2a4 e8g6 g1f2 e3g4 f2g1 c8a8 h2h3 g4e3 g1f2 e3d1 f2g1 d1c3 b1d3 c8c7 a4a5 f5f4 a5a6 g6d3 e2d3 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 19 seldepth 28 multipv 1 score cp 615 nodes 4001575 nps 9136015 tbhits 0 time 438 pv f7f5 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 18 seldepth 34 multipv 1 score cp 607 nodes 4001575 nps 9136015 tbhits 0 time 438 pv f7f5 a2a4 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> bestmove f7f5 ponder a2a4 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 << isready Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> readyok Apr 06 08:57:40 kknd python[23526]: ><> 1: Analysing chess960: https://lichess.org/RYXpN393#28 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 << position fen rbkqbnnr/pppppppp/8/8/8/8/PPPPPPPP/RBKQBNNR w KQkq - 0 1 moves d2d4 c7c6 f1e3 g8f6 g1f3 f8g6 c2c4 b8f4 e1d2 f4e3 d2e3 f6g4 d1c2 d7d5 c4d5 d8d5 c2c5 d5c5 d4c5 g4e3 f2e3 e7e6 f3e5 g6e5 c1h1 e5c4 b2b3 c4e3 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 << isready Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> readyok Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 << go movetime 4000 nodes 4000000 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 1 seldepth 1 multipv 1 score cp -445 nodes 148 nps 74000 tbhits 0 time 2 pv f1f3 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 2 seldepth 2 multipv 1 score cp -475 nodes 287 nps 143500 tbhits 0 time 2 pv f1f3 e3g4 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 3 seldepth 3 multipv 1 score cp -423 nodes 393 nps 196500 tbhits 0 time 2 pv f1f3 e3g4 f3g3 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 4 seldepth 4 multipv 1 score cp -339 nodes 690 nps 345000 tbhits 0 time 2 pv f1f3 e3f5 b1f5 e6f5 f3f5 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 5 seldepth 5 multipv 1 score cp -339 nodes 854 nps 427000 tbhits 0 time 2 pv f1f3 e3f5 b1f5 e6f5 f3f5 Apr 06 08:57:40 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 6 seldepth 6 multipv 1 score cp -453 nodes 1939 nps 969500 tbhits 0 time 2 pv f1f3 e3d5 b1d3 h7h5 a2a4 c8a8 Apr 06 08:57:41 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 7 seldepth 7 multipv 1 score cp -465 nodes 4345 nps 2172500 tbhits 0 time 2 pv f1f3 e3d5 f3g3 g7g6 b1e4 c8a8 g1f2 Apr 06 08:57:41 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 8 seldepth 8 multipv 1 score cp -470 nodes 7381 nps 2460333 tbhits 0 time 3 pv f1f3 e3d5 g1f2 c8c7 b1d3 d5c3 f3g3 g7g6 Apr 06 08:57:41 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 9 seldepth 15 multipv 1 score cp -495 nodes 37578 nps 5368285 tbhits 0 time 7 pv f1f3 e3d5 b1e4 c8a8 e4d5 d8d5 b3b4 d5d2 g1f2 f7f6 f3d3 d2d3 e2d3 e8g6 Apr 06 08:57:41 kknd python[23526]: ><> 1: ENGINE: 23549 >> info depth 10 seldepth 13 multipv 1 score cp -509 nodes 94776 nps 7290461 tbhits 0 time 13 pv f1f3 e3d5 f3g3 g7g6 g3f3 g6g5 h2h3 c8a8 b1d3 d5b4 a1d1 Apr 06 08:57:41 kknd python[23526]: Thread-1: ERROR: Could not send progress report. Continuing. Apr 06 08:57:41 kknd python[23526]: Traceback (most recent call last): Apr 06 08:57:41 kknd python[23526]: File "/home/cloud/.local/lib/python2.7/site-packages/fishnet.py", line 563, in run Apr 06 08:57:41 kknd python[23526]: timeout=HTTP_TIMEOUT) Apr 06 08:57:41 kknd python[23526]: File "/home/cloud/.local/lib/python2.7/site-packages/requests/sessions.py", line 555, in post Apr 06 08:57:41 kknd python[23526]: return self.request('POST', url, data=data, json=json, kwargs) Apr 06 08:57:41 kknd python[23526]: File "/home/cloud/.local/lib/python2.7/site-packages/requests/sessions.py", line 508, in request Apr 06 08:57:41 kknd python[23526]: resp = self.send(prep, send_kwargs) Apr 06 08:57:41 kknd python[23526]: File "/home/cloud/.local/lib/python2.7/site-packages/requests/sessions.py", line 618, in send Apr 06 08:57:41 kknd python[23526]: r = adapter.send(request, **kwargs) Apr 06 08:57:41 kknd python[23526]: File "/home/cloud/.local/lib/python2.7/site-packages/requests/adapters.py", line 490, in send Apr 06 08:57:41 kknd python[23526]: raise ConnectionError(err, request=request) Apr 06 08:57:41 kknd python[23526]: ConnectionError: ('Connection aborted.', BadStatusLine("''",)) Apr 06 08:57:55 kknd python[23526]: ><> 1: https://lichess.org/RYXpN393 took 20.1s (0.50s per position) Apr 06 08:58:17 kknd python[23526]: ><> 1: https://lichess.org/0mi9mKZE took 12.5s (0.48s per position) Apr 06 08:58:20 kknd python[23526]: [fishnet v1.15.9] Analyzed 3404 positions, crunched 13354 million nodes Apr 06 08:58:37 kknd python[23526]: ><> 1: https://lichess.org/5BDJu38q took 15.4s (0.47s per position) Apr 06 08:58:50 kknd python[23526]: ><> 1: https://lichess.org/N5f3fI9W took 12.6s (0.42s per position) Apr 06 08:59:20 kknd python[23526]: [fishnet v1.15.9] Analyzed 3511 positions, crunched 13774 million nodes Apr 06 08:59:24 kknd python[23526]: ><> 1: https://lichess.org/nWxKltWX took 20.6s (0.40s per position)

[niklasf]

Thanks. I recognize this time - it matches the site update this morning. I am tempted to just make the error message a little bit less scary (because failed progress reports are not a big deal, analysis will continue).

But just to be sure: What do you mean by "deep analysis"? In theory the same number of nodes should be analysed on all positions.

[allorder]

I though it was deep analysis because it give more information :

ENGINE: 23549 << isready ENGINE: 23549 >> bestmove f7f5 ponder a2a4

<> 1: Analysing chess960: https://lichess.org/RYXpN393#28 <> 1: ENGINE: 23549 >> info depth 2 seldepth 2 multipv 1 score cp -475 nodes 287 nps 143500 tbhits 0 time 2 pv f1f3 e3g4 ENGINE: 23549 << position fen rbkqbnnr/pppppppp/8/8/8/8/PPPPPPPP/RBKQBNNR w KQkq - 0 1 moves d2d4 c7c6 f1e3 g8f6 g1f3 f8g6 c2c4 b8f4 e1d2 f4e3 d2e3 f6g4 d1c2 d7d5 c4d5 d8d5 c2c5 d5c5 d4c5 g4e3 f2e3 e7e6 f3e5 g6e5 c1h1 e5c4 b2b3 c4e3 ENGINE: 23549 >> info depth 4 seldepth 4 multipv 1 score cp -339 nodes 690 nps 345000 tbhits 0 time 2 pv f1f3 e3f5 b1f5 e6f5 f3f5

etc

[niklasf]

Ah, I see. I tricked you there: By default fishnet keeps track of the more verbose log messages but does not print them. Then, when there is an error, it shows the verbose log so we get some context. (A higher verbosity level can be set, for example -vvv will always show the engine communication.)

Still glad you reported this. And of course thanks for helping to analyse games.

[allorder]

Thanks