CCT Logon

[hgm]

I tried to run bullet games between Fairy-Max under XBoard 4.4.4 on my 32-bit laptop, and ndeed at some point it got stuck. This happened when the kibitzing side (using -autoKibitz) was flooded with complaints that it was exceeding communication quota, and that its output would be delayed. I think this was also the side that got stuck.

My suspicion is that it has to do with this FICS limit on communication quota. (Which is especially severe if you are logged on as guest, which is the only way I can test.

[bob]

I tried to run bullet games between Fairy-Max under XBoard 4.4.4 on my 32-bit laptop, and ndeed at some point it got stuck. This happened when the kibitzing side (using -autoKibitz) was flooded with complaints that it was exceeding communication quota, and that its output would be delayed. I think this was also the side that got stuck.

My suspicion is that it has to do with this FICS limit on communication quota. (Which is especially severe if you are logged on as guest, which is the only way I can test.

Crafty never got a warning, because it only kibitzes 2 lines each time it makes a move (I don't put it into chatty-kathy mode in tournaments). I will try to help isolate this after the tournament ends...

[Michel]

Probably nothing to do with current problem but one thing to keep in mind is that FICS uses LF/CR as line terminator...

Rather than using one of the three standard line terminators

CR
LF
CR/LF

the programmers of FICS decided to use yet another one...

[hgm]

I was able to provoke another hang, in a bullet game WBtester vs FairyMax (both guest logins), this time making debug logs on both XBoards. The final part of the logs (where I edited out most debug messages coming from WB itself, just to show the communication) read:

<ICS: \012\015FairyMax(U)(----)[180] kibitzes: !!! +0.73/10 (0.14 sec, 50306 nodes, 357 knps)\012\015\ PV=h4e1 b4c4 e1g3 e3c5 d6e6 c5e3 a6a5 c4d3 e6d6\012\015fics%
<ICS: \007\012\015<12> -------- -------- p---k--- --B-p--- --K-P--- ------b- -------- -------- W -1 0 0 0 0 11 180 WBtester FairyMax 1 1 0 4 5 8023 5883 46 K/d6-e6 (0:00.937) Ke6 0 1 0\012\015fics%
1100829 >first : time 802
1100829 >first : otim 588
1100829 >first : d6e6
1100929 <first : 1 -76 0 5 c4c3
1100929 <first : 2 -81 0 11 c4c3 g3f4
1100929 <first : 2 -78 0 25 c4d3 g3f4
1100929 <first : 3 -78 0 68 c4d3 g3f4 c5e3
1100929 <first : 4 -78 0 113 c4d3 g3f4 c5e3
1100929 <first : 5 -78 0 716 c4d3 g3f4 c5e3
1100929 <first : 6 -78 0 1221 c4d3 g3f4 c5e3
1100929 <first : 7 -78 0 2686 c4d3 g3f4 c5e3
1100929 <first : 8 -76 2 11177 c4d3 g3f4 c5e3 f4e3 d3e3 a6a5 e3f3 a5a4
1100929 <first : 9 -76 6 28613 c4d3 g3f4 c5e3 f4e3 d3e3 a6a5 e3f3 a5a4 f3e3
1100978 <first : move c4d3
>ICS: c4d3\015\012
<ICS: \007\012\015<12> -------- -------- p---k--- --B-p--- ----P--- ---K--b- -------- -------- B -1 0 0 0 0 12 180 WBtester FairyMax -1 1 0 4 5 7481 5883 46 K/c4-d3 (0:00.542) Kd3 0 1 0\012\015fics%
<ICS: \012\015FairyMax(U)(----)[180] kibitzes: !!! +0.81/9 (0.07 sec, 26992 nodes, 380 knps) \012\015\ PV=e1g3 e3c5 d6e6 c5e3 e6f6 c4c3 f6g6 c3d3 g3f4 e3f4 e5f4\012\015fics%
<ICS: \012\015FairyMax(U)(----)[180] kibitzes: !!! +0.77/9 (0.18 sec, 54810 nodes, 303 knps) \012\015\ PV=d6e6 c5e3 g3f4 c4d3 e6d6\012\015fics%
<ICS: \012\015Game 180: Your opponent, FairyMax, has lost contact or quit.\012\015\012\015{Game 180 (WBtester vs. FairyMax) FairyMax forfeits by disconnection} 1-0\012\015\012\015No ratings adjustment done.\012\015fics%
GameEnds(37, FairyMax forfeits by disconnection, 0)
1202275 >first : result 1-0 {FairyMax forfeits by disconnection}
1202275 >first : force
1202275 >first : ping 4
>ICS: gameend\015\012
>ICS: \015\012

1137718 <first : 1 80 0 3 d6e6
1137718 <first : 2 80 0 4 d6e6
1137718 <first : 3 80 0 24 d6e6
1137718 <first : 4 80 0 33 d6e6
1137718 <first : 5 80 0 97 d6e6
1137718 <first : 6 80 0 144 d6e6
1137718 <first : 7 80 0 293 d6e6
1137718 <first : 8 77 4 22051 d6e6 c5e3 g3f4 c4d3 e6d6
1137767 <first : 9 77 18 54810 d6e6 c5e3 g3f4 c4d3 e6d6
1137779 <first : move d6e6
>ICS: d6e6\015\012
>ICS: kibitz !!! +0.77/9 (0.18 sec, 54810 nodes, 303 knps) PV=d6e6 c5e3 g3f4 c4d3 e6d6\015\012
<ICS: \012\015FairyMax(U)(----)[180] kibitzes: !!! +0.73/10 (0.14 sec, 50306 nodes, 357 knps)\012\015\ PV=h4e1 b4c4 e1g3 e3c5 d6e6 c5e3 a6a5 c4d3 e6d6\012\015(kibitzed to 1 player)\012\015fics%
<ICS: \007\012\015<12> -------- -------- p---k--- --B-p--- --K-P--- ------b- -------- -------- W -1 0 0 0 0 11 180 WBtester FairyMax -1 1 0 4 5 8023 5883 46 K/d6-e6 (0:00.937) Ke6 1 1 0\012\015fics%
GameEnds(40, xboard exit, 2)
Interrupting first
1239151 >first : force
1239151 >first : ping 4
1239151 >first : quit

What you can see is this.

Code: Select all

FairyMax at some point thinks, 
and decides on the move Kd6 (d6e6), 
which I highlighted in bold everywhere in the logs.

It is sent to FICS, 

the kibitz is sent with the PV for this move.

                                                                       WBtester gets the move Kd6 in a board

                                                                       XBoard feeds it to the engine

                                                                      After thinking the engine replies Kd3 (e3d3),
                                                                      which I highlighted in red everywhere.

                                                                      It is sent to FICS (WBtester was not set to kibitz)

FairyMax receives the delayed echo of an old kibitz (h4e1)

FairyMax receives the echo of its own move Kd6

And waits for the opponent' s move Kd3

and waits....

                                                                      WBtester receives the echo of ts move Kd3

                                                                      It receives a delayed kibitz for e1g3

                                                                      It receives the delayed kibitz for Kd6


and waits....

....

Until I quit its XBoard some time later

                                                                      WBtester is informed its opponent disconnected

The last move sent by WBtester is just never received by FairyMax. I don't think this is a XBoard error or crash. XBoad remains responsive, and I could quit it, and it closed the engine as it should. It must still be connected, as FICS notices very well when I quit it about 100 sec later. It just seems FICS at some point stops relaying the moves.

[F. Bluemers]

Just wondering,what's that slash doing?

4 5 8023 5883 46 K/d6-e6 (0:00.937) Ke6 1 1 0\012\015fics%

[hgm]

Just wondering,what's that slash doing?

4 5 8023 5883 46 K/d6-e6 (0:00.937) Ke6 1 1 0\012\015fics%

It is always there, in the board-12 format long move. In the ICS code the piece indicator is actually a string, so it could use "Ch" for Chancellor, and "Ca" for Cannon, and the slash is presumably added to make parsing easier. Although there never would be any ambiguity, as you could count back from the first digit. (But tht is assuming piece names cannot contain digits...)

[bob]

Just wondering,what's that slash doing?

4 5 8023 5883 46 K/d6-e6 (0:00.937) Ke6 1 1 0\012\015fics%

It is always there, in the board-12 format long move. In the ICS code the piece indicator is actually a string, so it could use "Ch" for Chancellor, and "Ca" for Cannon, and the slash is presumably added to make parsing easier. Although there never would be any ambiguity, as you could count back from the first digit. (But tht is assuming piece names cannot contain digits...)

Looking at logs, I believe we lost the last game yesterday on time, with another hang, but this time using 4.2.6, which suggests the problem is not the fault of 4.4.x as we had originally thought. I am trying to get it to hang and look at the debug file myself...

I suspect FICS changed something since the last tournament we held there, as I did not see any hangs at all. Something is new, and it is not about xboard...

[hgm]

I don't seem to be able to provoke any hangs now. Perhaps it depends on timeof day / server load. nfortunately people start games against FairyMax all the time (and manage to lose... ), preventing me to start new test games.

I wanted to redo the test, because it is not completely conclusive: if the XBoard ICS-input thread somehow hangs, it would probably also not print the input. And I had not tried to type any commands from the hanging player, to see if there was echo / response.

So this time I added a print statement to the debug every time the input routine returns. But alas, no more hangs...

[marcelk]

I don't seem to be able to provoke any hangs now. Perhaps it depends on timeof day / server load. nfortunately people start games against FairyMax all the time (and manage to lose... :lol: ), preventing me to start new test games.

I wanted to redo the test, because it is not completely conclusive: if the XBoard ICS-input thread somehow hangs, it would probably also not print the input. And I had not tried to type any commands from the hanging player, to see if there was echo / response.

So this time I added a print statement to the debug every time the input routine returns. But alas, no more hangs...

If it is FICS eating moves then other interfaces should suffer just as much, but they don't. I for example have 3 accounts continuously playing under robofics/icsdrone clones, and no issues with missing moves, never ever, for more than a decade... Also FICS has been up for almost 500 days, so any server side issue must have been there for a while. Further consider that FICS is still a single-threaded server (still handling 2000 connections, bravo!), its behavior would be very predictable and repeatable. Any bug must have been seen frequently before.

My money is that something is happening inside xboard. Not a lot of 24/7 online computers run under xboard at all. They only show up in these CC tourneys.

[hgm]

It is difficult to know for sure, as the error seems to have gone away now. I played dozens of bullet games, no hangs. This morning and yesterday the first or second game was a hang. I didn't change XBoard (I even went back to the bersion without the extra debug prints, to make sure tese did not cause the error to go away...)

Tomorrow morning I will try again, to see if it is time-of-day related.