behavior of -egtFormats

[jdart]

I am seeing this behavior with -egtFormats on the command line:

1. In ics mode (-ics specified) the engine starts up and then you can start a game (via "match") but xboard does not send the egtpath command (and also not "cores" or "memory"), not before the game is started and not after starting it. "egtpath" gets sent at the end of the game, after "result."

Command line for case 1:
xboard -keepAlive 5 -debugMode true -ics -zp -ponder -icshost winboard.nl -egtFormats "syzygy:/home/jdart/chess/syzygy" -fcp "/home/jdart/dev\
/arasan-chess/bin/arasanx-64-bmi2 -H 32G -c 24 -ics -t" -fd "/home/jdart/dev/arasan-chess/bin"

2. In offline mode, playing a match, egtpath and the other commands are sent right away after the engine sends "feature done=1" (they are sent after "result," too).

Command line for case 2:
xboard -debugMode true -zp -ponder -mg 10 -smpCores 12 -tc 5:0 -inc 1 -egtFormats "syzygy:/home/jdart/chess/syzygy" -fcp "/home/jdart/dev/ara\
san-chess/bin/arasanx-64-bmi2 -H 256m -c 12 -ics -t" -fd /home/jdart/dev/arasan-chess/bin -scp /home/jdart/chess/engines/crafty-25.2/crafty -\
sd /home/jdart/chess/engines/crafty-25.2

In both cases, the engine has sent "feature egt=syzygy".

log for the "deferred" case (case 1) follows (I think this is incorrect behavior).

Code: Select all

271 <first : Arasan v21.3.0-18-g2fd572f Copyright 1994-2019 by Jon Dart. All Rights Reserved.
10219 >first : new
random
10219 >first : post
10219 >first : hard
<ICS: \012\015             _       __     __                             __      \012\015            | |     / /__  / /________  ____ ___  __\
_     / /_____ \012\015            | | /| / / _ \/ / ___/ __ \/ __ `__ \/ _ \   / __/ __ \\012\015            | |/ |/ /  __/ / /__/ /_/ / / /\
 / / /  __/  / /_/ /_/ /\012\015            |__/|__/\___/_/\___/\____/_/ /_/ /_/\___/   \__/\____/ \012\015       ^^__                       \
                                 _  _  _ \012\015      /  - \_                                                     | || || |\012\015    <|   \
 __<            H.G.M's Variant Chess Server             |_______|\012\015    <|    \                                                       \\
__ ___ /\012\015    <|     \                                                       |___|_|\012\015    <|______\                              \
                        |_|___|\012\015     _|____|_                                                      |___|_|\012\015    (________)      \
                                              (_______)\012\015    /________\
ics input 0, castling = 7 0 4 7 0 4
<ICS:   /_______\ \012\015                                                           \012\015\012\015Head admin : admin    Complaints to : NO\
T_CONFIGURED\012\015Server location: NOT_CONFIGURED    Server version : 2.2.x-DEVEL\012\015Server name : NOT_CONFIGURED\012\015\012\015If you\
 are not a registered player enter the login name "guest"\012\015login:
ics input 0, castling = 7 0 4 7 0 4
21265 <first : # starting poll thread
21265 <first : # got cmd (main): xboard
21265 <first : # calling do_command(main):xboard
21265 <first : # do_command: xboard
21265 <first : # move text = xboard
21265 <first : # got cmd (main): protover 2
21265 <first : # calling do_command(main):protover 2
21265 <first : # do_command: protover 2
21265 <first : feature name=1 setboard=1 san=1 usermove=1 ping=1 ics=1 playother=0 sigint=0 colors=0 analyze=1 debug=1 memory=1 smp=1 variant\
s="normal" egt="syzygy" option="Favor frequent book moves -spin 50 1 100" option="Favor best book moves -spin 50 1 100" option="Favor high-we\
ighted book moves -spin 50 1 100" option="Can resign -check 1" option="Position learning -check 1" option="Strength -spin 100 0 100" option="\
Move overhead -spin 30 0 1000"
21265 >first : accepted name
21265 >first : accepted setboard
21265 >first : accepted san
21265 >first : accepted usermove
21265 >first : accepted ping
21265 >first : accepted ics
21265 >first : accepted playother
21265 >first : accepted sigint
21265 >first : accepted colors
21265 >first : accepted analyze
21265 >first : accepted debug
21265 >first : accepted memory
21265 >first : accepted smp
21265 >first : accepted variants
21265 >first : accepted egt
21265 >first : accepted option
21265 >first : accepted option
21265 >first : accepted option
21265 >first : accepted option
21265 >first : accepted option
21265 >first : accepted option
21265 >first : accepted option
21265 <first : myname="Arasan v21.3.0-18-g2fd572f"
21265 <first : feature done=0
21266 >first : accepted done
21281 <first : found 6-man Syzygy tablebases in directory /home/jdart/chess/syzygy:/home/jdart/chess/syzygy-6man/wdl:/home/jdart/chess/syzygy\
-6man/dtz
21281 <first : feature done=1
21281 >first : accepted done
21281 <first : # got cmd (main): new
21281 <first : # calling do_command(main):new
21281 <first : # do_command: new
21281 <first : # in save_game
21281 <first : # game_moves=0
21281 <first : # out of save_game
>ICS: arasanx\015\012
<ICS: \377\373\001
ics input 0, castling = 7 0 4 7 0 4

<WILL ECHO >DO ECHO <ICS: \012\015"ArasanX" is a registered name.  If it is yours, type the password.\012\015If not, just hit return to try a\
nother name.\012\015\012\015password:
ics input 0, castling = 7 0 4 7 0 4

<WILL ECHO >ICS: ******\015\012
<ICS: \377\374\001
ics input 0, castling = 7 0 4 7 0 4

<WONT ECHO >DONT ECHO <ICS: The HD of the old server machine suffered a head crash. As a result all \012\015accounts have been lost, and peop\
le should register anew.\012\015__________________________________________________________________________ \012\015Do 'help' for a list of th\
e commands that are available.\012\015Do 'help admins' for admin information, "=admin" for a list of all admins.\012\015Do 'help ficsfaq' for\
 answers to frequently asked questions.\012\015__________________________________________________________________________\012\015\012\015\012\
\015\012\015fics%
ics input 0, castling = 7 0 4 7 0 4

<WONT ECHO >ICS: alias $ @\015\012$set interface xboard 4.9.1 + arasanx-64-bmi2\015\012$iset startpos 1\015\012$iset ms 1\015\012$iset lock 1\
\015\012$style 12\015\012
>ICS: set width 80\015\012
<ICS: Alias $ replaced.\012\015fics%
ics input 0, castling = 7 0 4 7 0 4
<ICS: fics% startpos set\012\015fics% ms set\012\015fics% lock set\012\015fics% Style 12 set.\012\015fics% Width set to 80.\012\015fics%
ics input 0, castling = 7 0 4 7 0 4
>ICS: who\015\012
<ICS: \012\0152039 ArasanX(C)        1493 Bliep(C)           781 POS(C)          \012\0151931 rpiStockfish(C)   1478 rpiFruit(C)       ----:m\
amer(TD)       \012\0151538 rpiMinkoChess(C)  1152 rpiEmbla(C)       \012\0151531 Floyd(C)          1042 rpiBikjump(C)     \012\015\012\015 1\
0 players displayed (of 10). (*) indicates system administrator.\012\015fics%
ics input 0, castling = 7 0 4 7 0 4
29974 <first : kib Hello from Arasan v21.3.0-18-g2fd572f
29974 <first : # finished 'new' processing
29974 <first : # got cmd (main): random
29974 <first : # calling do_command(main):random
29974 <first : # do_command: random
29974 <first : # do_command: random
29974 <first : # got cmd (main): post
29974 <first : # calling do_command(main):post
29974 <first : # do_command: post
29974 <first : # got cmd (main): hard
29974 <first : # calling do_command(main):hard
29974 <first : # do_command: hard
29974 <first : # got cmd (main): accepted name
29974 <first : # calling do_command(main):accepted name
...
29975 <first : # do_command: accepted done
29975 <first : # move text = accepted done
>ICS: match rpistockfish 3 1 u\015\012
<ICS: Issuing: ArasanX (2039) rpiStockfish (1931) unrated blitz 3 1.\012\015--** rpiStockfish is a computer **--\012\015fics%
ics input 0, castling = 7 0 4 7 0 4
<ICS: \012\015rpiStockfish accepts your challenge.\012\015fics% \012\015Creating: rpiStockfish (1931) ArasanX (2039) unrated blitz 3 1\012\01\
5\012\015{Game 1 (rpiStockfish vs. ArasanX) Creating unrated blitz match.}\012\015\012\015<12> rnbqkbnr pppppppp -------- -------- -------- -\
------- PPPPPPPP RNBQKBNR W -1 1 1 1 1 0 1 rpiStockfish ArasanX -1 3 1 39 39 180 180 1 none (0:00) none 1 0\012\015fics%
ics input 0, castling = 7 0 4 7 0 4
Ratings from 'Creating:' rpiStockfish 1931, ArasanX 2039
recognized 'unrated blitz match.' (-1) as variant normal
Parsing board: rnbqkbnr pppppppp -------- -------- -------- -------- PPPPPPPP RNBQKBNR W -1 1 1 1 1 0 1 rpiStockfish ArasanX -1 3 1 39 39 180\
 180 1 none (0:00) none 1 0

recognized 'ICS unrated blitz match' (-1) as variant normal
ParseBoard says variant = 'ICS unrated blitz match'
recognized as normal
Remembered ratings: W 1931, B 2039
load 8x8 board
43531 >first : level 0 3 1
43532 >first : computer
43532 >first : name rpiStockfish
43532 >first : rating 2039 1931
Display title 'rpiStockfish(39) ArasanX(39) {3 1}, gameInfo.variant = 0'
43534 <first : # got cmd (main): level 0 3 1
43534 <first : # calling do_command(main):level 0 3 1
43534 <first : # do_command: level 0 3 1
43540 <first : # got cmd (main): computer
43540 <first : # calling do_command(main):computer
43540 <first : # do_command: computer
43540 <first : # got cmd (main): name rpiStockfish
43540 <first : # calling do_command(main):name rpiStockfish
43540 <first : # do_command: name rpiStockfish
43540 <first : # got cmd (main): rating 2039 1931
43540 <first : # calling do_command(main):rating 2039 1931
43540 <first : # do_command: rating 2039 1931
43540 <first : # contempt (calculated from ratings) = +0.27
<ICS: \012\015<12> rnbqkbnr pppppppp -------- -------- -------- -----N-- PPPPPPPP RNBQKB-R B -1 1 1 1 1 1 1 rpiStockfish ArasanX 1 3 1 39 39 \
180 180 1 N/g1-f3 (0:00) Nf3 1 0\012\015fics%
ics input 0, castling = 7 0 4 7 0 4
Parsing board: rnbqkbnr pppppppp -------- -------- -------- -----N-- PPPPPPPP RNBQKB-R B -1 1 1 1 1 1 1 rpiStockfish ArasanX 1 3 1 39 39 180 \
180 1 N/g1-f3 (0:00) Nf3 1 0




[H.G.Muller]

I don't quite understand the log. At t=10219 (ms) XBoard sends a "new", so presumably the engine has been started at this point. But Arasan reports receiving the "xboard" command, which should be the first thing that has been sent, and thus preceed aforementioned "new", only at t=21265. There is no mention of a new Arasan process being started in the mean time (nor of a new "xboard" being sent).

XBoard prints the memory, cores and egtpath commands together with 'new' (or actually the -initString) from a routine InitChessProgram(), which is also called in zippy mode when preparing the engine for a new game. (This happens pre-emptively immediately after a game finishes, there.) But at this time it apparently has had no response to the "protover" command yet; it receives the 'features', including the egt feature, only way later (20 sec!). So the engine startup sequence must have timed out long before (probably after 10 sec), leading XBoard to conclude it is dealing with a v1 engine that does not support any features (and thus also not egt) when it continues with InitChessProgram to send 'new'.

I don't see a legitimate reason why Arasan would need so much time, so probably you forgot to flush stdout after printing the features. If it really does need this much time, you should print (and flush) feature done=0 immediately after receiving 'protover' to extend the timeout period, not 20 sec later, after the timeout already occurred and the damage is already irreversibly done. Best practice is to print feature done=0 as the very first thing the engine prints.

[jdart]

Timeout would probably explain it, especially since I could not reproduce this on another system with the same version of xboard.

I think it is initializing the tablebases after protover which would explain the delay (I also sometimes run a debug version that has slower startup for other reasons).

--Jon

[H.G.Muller]

But how could it initialize EGT before it received the egtpath command? The log you posted seems incomplete, as I don't see the protover command in there that triggers the printing of features. It seems that Arasan's input thread only comes alive some 20 sec after Arasan printed its name. I suppose that starting it is the very first thing you do after printing the name, so you might have been struck by a glitch in the OS that made the starting of a thread take more than 20 sec. Delayed flushing cannot really be an explanation, as XBoard did not sent in anything after the new/post/hard after the timeout that could have caused a reply that triggered flushing.

Anyway, Arasan did manage to print its name quickly. To stay on the safe side, you could let it print a pre-emptive feature done=0 together with the name; XBoard doesn't really care if it receives this before or after it sends the protover command. You are supposed to send feature done=0 before anything that could take substantial time, and it seems that starting the input thread already can take substantial time. If you want to do it 'by the book' you should have the main process read the xboard and protover commands, reply with feature done=0, and only then start the input thread.