losses on time with xboard 4.7.3 and ICC

[jdart]

I have seen a couple instances of games lost on time on ICC. This is one example:

[pgn]
[Event "ICC 5 0"]
[Site "Internet Chess Club"]
[Date "2014.10.09"]
[Round "?"]
[White "DrunkenMasterB"]
[Black "ArasanX"]
[Result "1-0"]
[ECO "C65"]
[WhiteElo "2114"]
[BlackElo "2698"]
[PlyCount "49"]
[EventDate "2014.??.??"]
[TimeControl "300"]

1. e4 e5 2. Nf3 Nc6 3. Bb5 Nf6 4. d3 Bc5 5. c3 O-O 6. O-O d6 7. Nbd2 h6 8. Re1
Bd7 9. b4 Bb6 10. Nc4 a6 11. Bxc6 bxc6 12. a4 Re8 13. a5 Ba7 14. Be3 Bxe3 15.
Nxe3 Nh7 16. Rb1 Qf6 17. Qe2 Rab8 18. Red1 Nf8 19. g3 Ne6 20. Nh4 g6 21. Nf3
Nf8 22. Kg2 Qe6 23. Kh1 Nh7 24. Rg1 Kg7 25. Nd2 {Black forfeits on time} 1-0
[/pgn]

I only see this behavior when on the server and on Linux (i.e. with xboard, not Winboard). I have played thousands of games on Linux offline w/o
problems (mostly ponder off, though).

The last part of the xboard debug log follows. It appears the last user move (Nd2) is received, the engine starts searching, and then it outputs the move e6f6, which is a legal move. The log shows this going to ICS. And at that point it has used only a small part of the remaining time. The engine then starts to ponder. It is monitoring for input but I see no further input from the chess server before the time forfeit. Eventually though I see "<ICS: No such command (e6f6)" from the chess server.

Code: Select all

200882023 >first : usermove 200882023 >first : Nd2
nps: w=-1, b=-1
Display title 'DrunkenMasterB (33) vs. ArasanX (33) {5 0}, gameInfo.variant = 0'
200882129 <first &#58; # check_command&#58; time 22000
200882129 <first &#58; # check_command&#58; otim 15800
200882129 <first &#58; # check_command&#58; usermove Nd2
200882129 <first &#58; # move text = Nd2
200882129 <first &#58; # predicted move = g3-g4 last move = f3-d2
200882129 <first &#58; # ponder not ok
200882129 <first &#58; # adding to pending list usermove Nd2, list size=0
200882129 <first &#58; # terminating search &#40;controller&#41;
200882129 <first &#58; # time check interval=8318 elapsed_time=33108 target=9999999
200882129 <first &#58; # done pondering
200882129 <first &#58; # ponder move = h7-g5
200882129 <first &#58; # out of ponder&#40;)
200882129 <first &#58; # in check_pending
200882129 <first &#58; # move in pending stack
200882129 <first &#58; # ponder failed, exiting ponder loop
200882129 <first &#58; # got cmd &#40;main&#41;&#58; usermove Nd2
200882129 <first &#58; # calling do_command&#40;main&#41;&#58;usermove Nd2
200882129 <first &#58; # do_command&#58; usermove Nd2
200882129 <first &#58; # move text = Nd2
200882129 <first &#58; # got move&#58; Nd2
200882129 <first &#58; # execute_move&#58; f3-d2
200882129 <first &#58; # in search&#40;)
200882129 <first &#58; # movestogo=0 time_left=220000
200882129 <first &#58; # entering search, time_target = 6283
200882129 <first &#58; # xtra time = 12566
200882129 <first &#58;  1       8      0        0 Qh3
200882129 <first &#58;  1       8      0      102 Qh3
200882129 <first &#58;  2      -8      0      238 Ng5 Ndc4
200882129 <first &#58;  2      -8      0     1574 Ng5 Ndc4
200882129 <first &#58;  3      10      0     2067 Qh3 Qf3
200882130 <first &#58;  3      20      0     4914 Qh3 Ra1 Nf6
200882130 <first &#58;  4      20      0     5696 Ng5 g4 Qf6 Ra1
200882130 <first &#58;  4      20      0     5806 Ng5 g4 Qf6 Ra1
200882130 <first &#58;  5      28      0     6740 Ng5 Nf3 Nh3 Rgc1 f6
200882130 <first &#58;  6      20      0     8071 Ng5 Nf3 Nh3 Rgc1 Qf6 Ra1
200882130 <first &#58;  7      20      1    11412 Ng5 Rgc1 Qh3 Nf3 Nxf3 Qxf3 f6
200882130 <first &#58;  8      12      1    18653 Ng5 Rgc1 Qh3 Nf3 Nxf3 Qxf3 c5 bxc5 dxc5
200882130 <first &#58;  9      12      2    35570 Ng5 Nf3 Nh3 Rgf1 Qf6 Ng1 Nxg1 Rxg1 Bh3
200882130 <first &#58; 10      16      3    48155 Ng5 Nf3 Qh3 Rgf1 Nxf3 Qxf3 f6 Rfc1 Be6 d4
200882130 <first &#58; 11       8      6   125401 Ng5 Nf3 Qh3 Rgc1 Nxf3 Qxf3 f6 d4 Rbd8 Rd1 Ra8
200882167 <first &#58; 12      12     14   297253 Ng5 Nf3 Qh3 Rge1 Nxf3 Qxf3 f6 Rec1 Be6 d4 Rbd8 Ra1
200882235 <first &#58; # time check interval=3294 elapsed_time=211 target=6283
200882235 <first &#58; 13      12     21   556102 Ng5 Nf3 Qh3 Rge1 Nxf3 Qxf3 f6 Rec1 Be6 d4 Rf8 dxe5 dxe5
200882378 <first &#58; # time check interval=3903 elapsed_time=354 target=6283
200882378 <first &#58; 14      12     35  1105384 Ng5 Nf3 Qh3 Rge1 Nxf3 Qxf3 f6 Rec1 Be6 d4 Rf8 Qe2 exd4 cxd4
200882571 <first &#58; # time check interval=4164 elapsed_time=547 target=6283
200882571 <first &#58; 15      12     54  1822467 Ng5 Rgf1 Qf6 f3 Bh3 Rfc1 Be6 Ng4 Qe7 Ne3 Rh8 f4 exf4 gxf4 Nh3
200883257 <first &#58; # time check interval=5649 elapsed_time=1233 target=6283
200883257 <first &#58; 16      12    123  5572445 Ng5 Rgf1 Qf6 f3 Bh3 Rfc1 Be6 Ng4 Qe7 Ne3 Rh8 f4 exf4 gxf4 Nh3
200884122 <first &#58; # adding time due to low score, new target=18849
200884237 <first &#58; 16      -8    221 12003188 Qf6 Rgf1 Bh3 Rg1 h5 Nf3 Bg4 Nxg4 hxg4 Nh4 c5 Rgc1 Red8 Qe3 cxb4 cxb4
200885558 <first &#58; # time check interval=7449 elapsed_time=3533 target=18849
200885558 <first &#58; 16      -8    353 21056416 Qf6 Rgf1 Bh3 Rg1 h5 Nf3 Bg4 Nxg4 hxg4 Nh4 c5 Rgc1 Red8 Qe3 cxb4 cxb4
200886174 <first &#58; # time check interval=7399 elapsed_time=4150 target=18849
200886174 <first &#58; 17      -4    415 24566824 Qf6 Rgf1 Bh3 Rg1 h5 Nf3 Rbd8 g4 hxg4 Nxg4 Qf4 Ne3 Kh8 Rg3 Qh6 Qa2 Be6
200886978 <first &#58; # time check interval=7229 elapsed_time=4954 target=18849
200886978 <first &#58; 18       4    495 28652094 Qf6 Rgf1 Bh3 Rfc1 Ng5 f3 h5 d4 Ra8 d5 Bd7 dxc6 Bxc6 Nd5 Bxd5 exd5 Qf5 Qe3
200890634 <first &#58; # time check interval=3847 elapsed_time=8610 target=18849
200890634 <first &#58; 19       0    861 52999204 Qf6 Qf3 Qxf3+ Nxf3 Ng5 Nxg5 hxg5 Kg2 Rh8 f3 f5 exf5 gxf5 Rge1 Kf6 d4 exd4 cxd4 g4 fxg4 fxg4
<ICS&#58; aics% 
ics input 49, castling = 45 45 7 45 45 45
200894257 <first &#58; # time check interval=3861 elapsed_time=12233 target=18849
200894257 <first &#58; 20       3   1223 75571548 Qf6 Qf3 Qe7 Qe2 Ng5 Nf3 Qe6
200900877 <first &#58; # terminating, time up
200900877 <first &#58; # terminating, time up
200900877 <first &#58; # terminating search &#40;controller&#41;
200900877 <first &#58; # time check interval=4005 elapsed_time=18853 target=18849
200900877 <first &#58; # search done &#58; move = e6-f6
200900877 <first &#58; 21       3   1885 120817238 Qf6 Qf3 Qe7 Qe2 Ng5 Nf3 Qe6
200900877 <first &#58; # state = 0
200900877 <first &#58; # game_end = 0
200900877 <first &#58; # in check_pending
200900877 <first &#58; move e6f6
>ICS&#58; e6f6\015\012
200900960 <first &#58; tellics kibitz time=18.85 sec. score=+0.03 depth=21 nps=6.41M cpu=757.03% pv&#58; Qf6 Qf3 Qe7 Qe2 Ng5 Nf3 Qe6
>ICS&#58; kibitz time=18.85 sec. score=+0.03 depth=21 nps=6.41M cpu=757.03% pv&#58; Qf6 Qf3 Qe7 Qe2 Ng5 Nf3 Qe6
>ICS&#58; \015\012
200900960 <first &#58; # in check_pending
200900960 <first &#58; # in ponder&#40;), move = e6-f6 predicted reply = e2-f3
200900960 <first &#58; # starting to ponder
200900960 <first &#58; # 1. move=&#40;null&#41; score=4508640 terminate=0
200900960 <first &#58; # 2. move=f6xf3 score=-4 terminate=0
200900960 <first &#58; # 3. move=f6-e7 score=4 terminate=0
200900960 <first &#58; # 4. move=f6-e7 score=4 terminate=0
200900960 <first &#58; # 5. move=f6xf3 score=-4 terminate=0
200900960 <first &#58; # 6. move=f6-e7 score=4 terminate=0
200900960 <first &#58; # 7. move=f6-e7 score=4 terminate=0
200900960 <first &#58; # 8. move=f6-e7 score=4 terminate=0
200900960 <first &#58; # 9. move=f6-e7 score=3 terminate=0
200900960 <first &#58; # 10. move=f6-e7 score=0 terminate=0
200900960 <first &#58; # 11. move=f6-e7 score=4 terminate=0
200900960 <first &#58; # 12. move=f6-e7 score=4 terminate=0
200900960 <first &#58; # 13. move=f6-e7 score=4 terminate=0
200900960 <first &#58; # 14. move=f6-e7 score=4 terminate=0
200900971 <first &#58; # 15. move=f6-e7 score=4 terminate=0
200901171 <first &#58; # time check interval=5544 elapsed_time=294 target=9999999
200901171 <first &#58; # 16. move=f6-e6 score=3 terminate=0
200901285 <first &#58; # time check interval=5046 elapsed_time=407 target=9999999
200901285 <first &#58; # 17. move=f6-e6 score=3 terminate=0
200901455 <first &#58; # time check interval=5367 elapsed_time=578 target=9999999
200901455 <first &#58; # 18. move=f6-e6 score=0 terminate=0
200902338 <first &#58; # time check interval=6403 elapsed_time=1461 target=9999999
200902339 <first &#58; # 19. move=f6xf3 score=4 terminate=0
<ICS&#58; aics% 
ics input 50, castling = 45 45 7 45 45 45
200903932 <first &#58; # time check interval=7233 elapsed_time=3055 target=9999999
200903932 <first &#58; # 20. move=f6-e7 score=8 terminate=0
200906566 <first &#58; # time check interval=7500 elapsed_time=5689 target=9999999
200906566 <first &#58; # 21. move=f6-e7 score=4 terminate=0
200907759 <first &#58; # time check interval=7430 elapsed_time=6882 target=9999999
200907759 <first &#58; # 22. move=f6-e7 score=4 terminate=0
200935600 <first &#58; # time check interval=8522 elapsed_time=34723 target=9999999
200935600 <first &#58; # 23. move=f6xf3 score=12 terminate=0
200939664 <first &#58; # time check interval=8469 elapsed_time=38787 target=9999999
200939664 <first &#58; # 24. move=f6xf3 score=8 terminate=0
200950182 <first &#58; # time check interval=8515 elapsed_time=49304 target=9999999
200950182 <first &#58; # 25. move=f6xf3 score=12 terminate=0
200959649 <first &#58; # time check interval=8529 elapsed_time=58772 target=9999999
200959649 <first &#58; # 26. move=f6xf3 score=12 terminate=0
200978483 <first &#58; # time check interval=8623 elapsed_time=77606 target=9999999
200978483 <first &#58; # 27. move=f6xf3 score=12 terminate=0
201030768 <first &#58; # time check interval=8879 elapsed_time=129891 target=9999999
201030768 <first &#58; # 28. move=f6xf3 score=20 terminate=0
>ICS&#58; date\015\012
201087806 <first &#58; # time check interval=9059 elapsed_time=186929 target=9999999
201087806 <first &#58; # 29. move=f6xf3 score=12 terminate=0
201209179 <first &#58; # time check interval=9216 elapsed_time=308301 target=9999999
201209179 <first &#58; # 30. move=f6xf3 score=16 terminate=0
>ICS&#58; date\015\012
<ICS&#58; aics% aics% aics% aics% aics% aics% aics% aics% aics% aics% aics% aics% aics% aics% aics% aics% aics% aics% \015\012<12> -r--r--- --pb-pkn p-ppq-pp P---p--- -P--P--- --PPN-P- ---NQP-P -R----RK B -1 0 0 0 0 9 952 DrunkenMasterB ArasanX 1 5 0 33 33 158 0 25 N/f3-d2 &#40;0&#58;33&#41; Nd2 1\015\012&#123;Game 952 &#40;DrunkenMasterB vs. ArasanX&#41; ArasanX forfeits on time&#125; 1-0\015\012Blitz rating adjustment&#58; 2729 --> 2698\015\012aics% \015\012Challenge&#58; DrunkenMasterB &#40;2114&#41; ArasanX &#40;2698&#41; rated Blitz 5 0\015\012Estimated rating changes&#58; Loss&#58; -31    Draw&#58; -15   Win&#58; +1\015\012DrunkenMasterB is in the computer list.\015\012You may accept this with "accept DrunkenMasterB", decline it with\015\012"decline DrunkenMasterB", or propose different parameters.\015\012aics% 
ics input 50, castling = 45 45 7 45 45 45
Parsing board&#58; -r--r--- --pb-pkn p-ppq-pp P---p--- -P--P--- --PPN-P- ---NQP-P -R----RK B -1 0 0 0 0 9 952 DrunkenMasterB ArasanX 1 5 0 33 33 158 0 25 N/f3-d2 &#40;0&#58;33&#41; Nd2 1

load 8x8 board
parseboard 49, castling = 45 45 7 45 45 45
accepted move Nd2 from ICS, parse it.
moveNum = 49
board = 0-8 x 8
Move parsed to 'Nd2 &#40;0&#58;33&#41;'
nps&#58; w=-1, b=-1
Display title 'DrunkenMasterB &#40;33&#41; vs. ArasanX &#40;33&#41; &#123;5 0&#125;, gameInfo.variant = 0'
GameEnds&#40;25, ArasanX forfeits on time, 0&#41;
201274443 >first &#58; result 1-0 &#123;ArasanX forfeits on time&#125;
201274444 >first &#58; force
201274444 >first &#58; ping 140
>ICS&#58; gameend\015\012
>ICS&#58; \015\012
Reset&#40;1, 1&#41; from gameMode 11
recognized 'normal' (-1&#41; as variant normal
GameEnds&#40;0, &#40;null&#41;, 2&#41;
shuffleOpenings = 0
201274452 >first &#58; memory 68
201274452 >first &#58; egtpath nalimov /egtb
201274452 >first &#58; cores 1
201274452 >first &#58; new
random
201274452 >first &#58; ics chessclub.com
201274452 >first &#58; post
201274452 >first &#58; hard
201274452 >first &#58; ping 141
recognized 'Blitz' (-1&#41; as variant normal
>ICS&#58; /tell DrunkenMasterB I'm not quite ready for a new game yet; try again soon.\015\012/decline DrunkenMasterB\015\012
201274456 <first &#58; # check_command&#58; result 1-0 &#123;ArasanX forfeits on time&#125;
201274456 <first &#58; # adding to pending list result 1-0 &#123;ArasanX forfeits on time&#125;, list size=0
201274456 <first &#58; # received_result&#58; result 1-0 &#123;ArasanX forfeits on time&#125;
201274456 <first &#58; # terminating search &#40;controller&#41;
201274456 <first &#58; # time check interval=9337 elapsed_time=373566 target=9999999
201274456 <first &#58; # done pondering
201274456 <first &#58; # ponder move = f6xf3
201274456 <first &#58; # out of ponder&#40;)
201274456 <first &#58; # in check_pending
201274456 <first &#58; # adding to pending list force, list size=1
201274456 <first &#58; # calling do_command from check_pending
201274456 <first &#58; # removing result 1-0 &#123;ArasanX forfeits on time&#125;
201274456 <first &#58; # do_command&#58; result 1-0 &#123;ArasanX forfeits on time&#125;
201274456 <first &#58; # adding to pending list ping 140, list size=1
201274456 <first &#58; # in save_game
201274456 <first &#58; # game_moves=50
201274456 <first &#58; # calling classify
201274456 <first &#58; # out of save_game
201274456 <first &#58; # calling do_command from check_pending
201274456 <first &#58; # removing force
201274456 <first &#58; # do_command&#58; force
201274456 <first &#58; # calling do_command from check_pending
201274456 <first &#58; # removing ping 140
201274456 <first &#58; # do_command&#58; ping 140
201274456 <first &#58; pong 140
201274456 <first &#58; # ponder failed, exiting ponder loop
201274456 <first &#58; # adding to pending list memory 68, list size=0
201274456 <first &#58; # adding to pending list egtpath nalimov /egtb, list size=1
201274456 <first &#58; # adding to pending list cores 1, list size=2
201274456 <first &#58; # adding to pending list new, list size=3
201274456 <first &#58; # adding to pending list random, list size=4
201274456 <first &#58; # adding to pending list ics chessclub.com, list size=5
201274456 <first &#58; # adding to pending list post, list size=6
201274456 <first &#58; # adding to pending list hard, list size=7
201274456 <first &#58; # adding to pending list ping 141, list size=8
201274456 <first &#58; # got cmd &#40;main&#41;&#58; memory 68
201274456 <first &#58; # calling do_command&#40;main&#41;&#58;memory 68
201274456 <first &#58; # do_command&#58; memory 68
201274456 <first &#58; # got cmd &#40;main&#41;&#58; egtpath nalimov /egtb
201274456 <first &#58; # calling do_command&#40;main&#41;&#58;egtpath nalimov /egtb
201274456 <first &#58; # do_command&#58; egtpath nalimov /egtb
201274456 <first &#58; # setting Nalimov tb path to \egtb
201274456 <first &#58; # got cmd &#40;main&#41;&#58; cores 1
201274456 <first &#58; # calling do_command&#40;main&#41;&#58;cores 1
201274456 <first &#58; # do_command&#58; cores 1
201274456 <first &#58; # got cmd &#40;main&#41;&#58; new
201274456 <first &#58; # calling do_command&#40;main&#41;&#58;new
201274456 <first &#58; # do_command&#58; new
201274456 <first &#58; # in save_game
201274456 <first &#58; # game_moves=0
201274456 <first &#58; # out of save_game
<ICS&#58; No such command &#40;e6f6&#41;.\015\012aics% 
ics input 0, castling = 7 0 4 7 0 4

[Joost Buijs]

Do you see this behaviour with xboard only?

Recently I had some unexplainable losses in time on ICC as well.
Sometimes I also see the message 'no such command' passing by.
I didn't look at it in any detail, but it can very well be that the problem started when I switched from winboard 4.7.2 to 4.7.3a.

[hgm]

Well, it looks like a problem outside XBoard, if it sends the move, and then gets no response. Were you playing with timestamp here, or connected to ICC directly?

What is also strange is the large number of ICS prompts ('aics%') that we get before receiving the board that gives us the time forfeit. XBoard did send two 'date' commands after the move, to which there also isn't any response.

It looks a bit like there was a breakdown of communication, that what XBoard sent was just stashed somewhere without the ICS seeing it minutes later, when the game was already finished.

XBoard should really disconnect when it does not get a reply to the date command before it sends the next. I don't recall anymore if I implemented that in XBoard 4.8.0, or that it was just in the floodgate adaptor. But I guess it would not prevent you from forfeiting on time, if the ICS really cannot see what you are doing.

[bob]

Do you see this behaviour with xboard only?

Recently I had some unexplainable losses in time on ICC as well.
Sometimes I also see the message 'no such command' passing by.
I didn't look at it in any detail, but it can very well be that the problem started when I switched from winboard 4.7.2 to 4.7.3a.

There are some time losses in newer xboards. This affects (for me) mainly zero inc games. The animations are not free. And the system("aplay") also adds a delay, caused by the fork() needed to create the new process. I have seen overhead in the .1 second and up range, which can be problematic with 0 increment games.

[jdart]

I am not running with timestamp. Possibly really severe lag might cause this issue but it would have to be bad because it was not nearly running out of time. There are a lot of date commands because the -keepAlive option is on.

--Jon

[hgm]

Yes, there are lots of date commands. But not a single response to them. Which is fishy. When you send a date command, you would expect to see a date...

[jdart]

That also might point to lag. Maybe I should try with timestamp. Note though it did keep playing after this game and seemed to be ok.

--Jon

[Joost Buijs]

Do you see this behaviour with xboard only?

Recently I had some unexplainable losses in time on ICC as well.
Sometimes I also see the message 'no such command' passing by.
I didn't look at it in any detail, but it can very well be that the problem started when I switched from winboard 4.7.2 to 4.7.3a.

There are some time losses in newer xboards. This affects (for me) mainly zero inc games. The animations are not free. And the system("aplay") also adds a delay, caused by the fork() needed to create the new process. I have seen overhead in the .1 second and up range, which can be problematic with 0 increment games.

Indeed, I have the time losses mainly with zero inc. games.
I turned off all sounds, that didn't help much. I will try to turn off all animations to see if that makes any difference.
The timing in my engine is sub millisecond, I don't expect the problem to be there.
I never had this problem in the past, it is just something that appeared a couple of months ago.

[bob]

Do you see this behaviour with xboard only?

Recently I had some unexplainable losses in time on ICC as well.
Sometimes I also see the message 'no such command' passing by.
I didn't look at it in any detail, but it can very well be that the problem started when I switched from winboard 4.7.2 to 4.7.3a.

There are some time losses in newer xboards. This affects (for me) mainly zero inc games. The animations are not free. And the system("aplay") also adds a delay, caused by the fork() needed to create the new process. I have seen overhead in the .1 second and up range, which can be problematic with 0 increment games.

Indeed, I have the time losses mainly with zero inc. games.
I turned off all sounds, that didn't help much. I will try to turn off all animations to see if that makes any difference.
The timing in my engine is sub millisecond, I don't expect the problem to be there.
I never had this problem in the past, it is just something that appeared a couple of months ago.

I think you can go to options and then sounds and "blank out" the aplay command, but I am not sure that has solved all the issues yet...

[hgm]

There are also less extreme measures: the Sound Options dialog allows you to choose a sound for each 'event' separately, and 'No Sound' is on that menu. If that is selected XBoard will also see no reason to invoke aplay (or whatever sound program you configured) when the event occurs. So you can for instance switch the 'move' sound off, but still make a phone ring if someone sends you a personal tell, or a sound a gong when you are challenged.