possible xboard bug?

[jdart]

I've been using a development shapshot from Jan., mostly without problems. Recently though I saw a case where my program was hanging and not moving on ICC. It looks like what happened was this:

1. Arasan sends a move, Ke1

2. Opponent (crafty) sends a draw request

3. Arasan accepts ("offer draw")

4. Crafty sends a move (Kf7) - this is ignored.

5. A rematch request is sent, and the standard new game commands get sent.

6. Crafty sends e4

7. Arasan sends c5

8. xboard says "Undoing extra move from first, gameMode 13" and sends an undo command.

I've looked through the log and I don't see Arasan sending an extra move. But it obeys the undo command and backs up half a move. Last part of debug log follows.

<ICS: \015\012<12> -------- -------- -p-p-k-- -P--pP-- --PpP--p -------P -------- ----K--- B -1 0 0 0 0 4 204 ArasanX crafty -1 15 3 5 5 108 21 74 K/d2-e1 (0:10) Ke1 0\015\012aics%
ics input 147, castling = 45 45 11 45 45 10
Parsing board: -------- -------- -p-p-k-- -P--pP-- --PpP--p -------P -------- ----K--- B -1 0 0 0 0 4 204 ArasanX crafty -1 15 3 5 5 108 21 74 K/d2-e1 (0:10) Ke1 0

load 8x8 board
parseboard 147, castling = 45 45 4 45 45 10
accepted move Ke1 from ICS, parse it.
moveNum = 147
board = 0-8 x 8
move to parse: Ke1
Parser Qa1: yyleng=3, 21(-1,-1)-(4,0) = 0 ( )
Disambiguate in: 21(-1,-1)-(4,0) = 0 (-)
Disambiguate out: 21(3,1)-(4,0) = 0 (-)
CoordsToAlgebraic, piece=21 (3,1)-(4,0) -
MateTest: K=1, my=6, his=6
Move parsed to 'Ke1 (0:10)'
nps: w=-1, b=-1
Display title 'ArasanX (5) vs. crafty (5) {15 3}, gameInfo.variant = 0'
<ICS: ArasanX(C) kibitzes: time=10.40 sec. score=+0.02 depth=26 nps=3.37M egtb:1/1 cpu:321.49% pv: Ke1 Kg7 Kd1 Kf7 Kc1 Kf6 Kb1 Kg7 Ka2 Kf6 Kb2 Kg5 Ka3 Kf6 Kb4 Kg5 Kb3 Kh6 Kc2 Kg5 Kd1 Kh6 Kd2 Kg5 Ke2\015\012(kibitzed to 2 people)\015\012aics%
ics input 147, castling = 45 45 4 45 45 10
2492042 <first : # time check interval=171390 elapsed_time=231 target=99999
2492042 <first : # 25. move=e1-f2 score=2 terminate=0
<ICS: \015\012Your opponent offers you a draw.\015\012\007Use "draw" to accept. The offer is valid until you make a move.\015\012aics%
ics input 147, castling = 45 45 4 45 45 10
2495079 >first : draw
2495126 <first : # read 5 bytes
2495127 <first : # check_command: draw
2495127 <first : # in accept_draw
2495127 <first : # checking draw score ..
2495127 <first : # rating_diff = 83
2495127 <first : # draw_score = 0
2495127 <first : # last_score = -48
2495127 <first : # threshold = 34
2495127 <first : offer draw
>ICS: /
>ICS: draw\015\012
<ICS: \007\015\012<12> -------- -----k-- -p-p---- -P--pP-- --PpP--p -------P -------- ----K--- W -1 0 0 0 0 5 204 ArasanX crafty 1 15 3 5 5 108 19 75 K/f6-f7 (0:05) Kf7 0\015\012aics%
ics input 147, castling = 45 45 4 45 45 10
Parsing board: -------- -----k-- -p-p---- -P--pP-- --PpP--p -------P -------- ----K--- W -1 0 0 0 0 5 204 ArasanX crafty 1 15 3 5 5 108 19 75 K/f6-f7 (0:05) Kf7 0

load 8x8 board
parseboard 148, castling = 45 45 4 45 45 10
accepted move Kf7 from ICS, parse it.
moveNum = 148
board = 0-8 x 8
move to parse: Kf7
Parser Qa1: yyleng=3, 43(-1,-1)-(5,6) = 0 ( )
Disambiguate in: 43(-1,-1)-(5,6) = 0 (-)
Disambiguate out: 43(5,5)-(5,6) = 0 (-)
CoordsToAlgebraic, piece=43 (5,5)-(5,6) -
MateTest: K=1, my=6, his=6
Move parsed to 'Kf7 (0:05)'
time odds: 1.000000 1.000000
2495804 >first : time 10800
2495804 >first : otim 1900
book hit = (NULL)
2495804 >first : usermove 2495804 >first : Kf7
AnimateMove: piece 43 slides from 5,5 to 5,6
nps: w=-1, b=-1
Display title 'ArasanX (5) vs. crafty (5) {15 3}, gameInfo.variant = 0'
2495877 <first : # read 34 bytes
2495877 <first : # check_command: time 10800
2495877 <first : # check_command: otim 1900
2495877 <first : # check_command: usermove Kf7
2495877 <first : # move text = Kf7
2495877 <first : # predicted move = f6-g7 last move = f6-f7
2495877 <first : # ponder not ok
2495877 <first : # adding to pending list Kf7, list size=0
2495877 <first : # terminating search (controller)
2495877 <first : # terminating, command input received
2495877 <first : # terminating, time up
2495877 <first : # terminating search (controller)
2495877 <first : # time check interval=170378 elapsed_time=608 target=99999
2495877 <first : # done pondering
2495877 <first : # ponder move = e1-f2
2495877 <first : # out of ponder()
2495877 <first : # move in pending stack
2495877 <first : # move in pending stack
2495877 <first : # ponder failed, move in stack
2495877 <first : # got move: Kf7
2495877 <first : # execute_move: f6-f7
2495877 <first : # in search()
2495877 <first : # zero inc time = 337
2495877 <first : # time after inc adj = 562
2495877 <first : # after opp time adjust: 1002
2495877 <first : # entering search, time_target = 1002
2495877 <first : # xtra time = 1002
2495877 <first : 0 -120 0 3 f6 Kxf6
2495878 <first : 0 52 0 8 Kf2 Ke7
2495879 <first : 0 56 0 10 Ke2 Kf6
2495879 <first : 1 32 0 24 Ke2 Kf6
2495879 <first : 2 40 0 60 Ke2 Kf6 Kf3
2495879 <first : 3 4 0 193 Ke2 Kg7 Kd1 d3
2495879 <first : 4 2 0 289 Ke2 Kg7 Kd1 Kf7
2495879 <first : 5 2 0 377 Ke2 Kg7 Kd1 Kf7 Kc1
2495879 <first : 6 2 0 499 Ke2 Kg7 Kd1 Kf7 Kc1
2495879 <first : 7 2 0 622 Ke2 Kg7 Kd1 Kf7 Kc1
2495879 <first : 8 2 0 764 Ke2 Kg7 Kd1 Kf7 Kc1
2495880 <first : 9 2 1 892 Ke2 Kg7 Kd1 Kf7 Kc1
2495880 <first : 10 2 1 1063 Ke2 Kg7 Kd1 Kf7 Kc1
2495880 <first : 11 2 1 1245 Ke2 Kg7 Kd1 Kf7 Kc1
2495880 <first : 12 2 1 1422 Ke2 Kg7 Kd1 Kf7 Kc1
2495880 <first : 13 2 1 1601 Ke2 Kg7 Kd1 Kf7 Kc1
2495880 <first : 14 2 1 1775 Ke2 Kg7 Kd1 Kf7 Kc1
2495880 <first : 15 2 1 1955 Ke2 Kg7 Kd1 Kf7 Kc1
2495880 <first : 16 2 1 2142 Ke2 Kg7 Kd1 Kf7 Kc1
2495880 <first : 17 2 1 2319 Ke2 Kg7 Kd1 Kf7 Kc1
2495880 <first : 18 2 1 4764 Ke2 Kg7 Kd1 Kf7 Kc1
2495880 <first : 19 2 1 7679 Ke2 Kg7 Kd1 Kf7 Kc1
2495880 <first : 20 2 1 15108 Ke2 Kg7 Kd1 Kf7 Kc1
2495881 <first : 21 2 3 62316 Ke2 Kg7 Kd1 Kf7 Kc1
2495890 <first : 22 2 7 174565 Ke2 Kg7 Kd1 Kf7 Kc1
2496068 <first : 23 2 25 715188 Ke2 Kg7 Kd1 Kf7 Kc1
2496501 <first : 24 2 68 2120366 Ke2 Kg7 Kd1 Kf7 Kc1
<ICS: {Game 204 (ArasanX vs. crafty) Game drawn by mutual agreement} 1/2-1/2\015\012Standard rating adjustment: 2559 --> 2563\015\012aics%
ics input 148, castling = 45 45 4 45 45 10
GameEnds(39, Game drawn by mutual agreement, 0)
2496655 >first : result 1/2-1/2 {Game drawn by mutual agreement}
2496656 >first : force
2496656 >first : ping 2
>ICS: gameend\015\012
>ICS: \015\012
Reset(1, 1) from gameMode 11
recognized 'normal' (-1) as variant normal
GameEnds(0, (null), 2)
shuffleOpenings = 0
2496657 >first : new
random
2496657 >first : ics chessclub.com
2496657 >first : post
2496657 >first : hard
2496657 >first : ping 3
2496700 <first : # read 107 bytes
2496700 <first : # check_command: result 1/2-1/2 {Game drawn by mutual agreement}
2496700 <first : # adding to pending list result 1/2-1/2 {Game drawn by mutual agreement}, list size=0
2496700 <first : # received_result: result 1/2-1/2 {Game drawn by mutual agreement}
2496700 <first : # check_command: force
2496700 <first : # check_command: ping 2
2496700 <first : # check_command: new
2496700 <first : # adding to pending list new, list size=1
2496700 <first : # check_command: random
2496700 <first : # check_command: ics chessclub.com
2496700 <first : # check_command: post
2496700 <first : # check_command: hard
2496700 <first : # check_command: ping 3
2496700 <first : # terminating search (controller)
2496700 <first : # terminating, command input received
2496700 <first : # terminating, time up
2496700 <first : # terminating search (controller)
2496700 <first : # search done : move = e1-e2
2496700 <first : # state = 0
2496700 <first : # game_end = 1
2496700 <first : # game end signal in pending stack
2496700 <first : # in do_pending, list size=2
2496700 <first : # pending command: result 1/2-1/2 {Game drawn by mutual agreement}
2496700 <first : # do_command: result 1/2-1/2 {Game drawn by mutual agreement}
2496701 <first : # in save_game
2496701 <first : # calling classify
2496701 <first : # out of save_game
2496701 <first : # pending command: new
2496701 <first : # do_command: new
2496701 <first : # in save_game
2496701 <first : # out of save_game
2496810 <first : kib Hello from Arasan 12.0
2496810 <first : # out of do_pending, list size=0
<ICS: Your ad is #355\015\012(ad sent to 513 players, of whom 97 are eligible)\015\012Your ad is #443\015\012(ad sent to 513 players, of whom 78 are eligible)\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
>ICS: date\015\012
<ICS: Sun Apr 04 19:19:22 EDT (New York time)\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
>ICS: date\015\012
<ICS: Sun Apr 04 19:22:22 EDT (New York time)\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
>ICS: date\015\012
<ICS: Sun Apr 04 19:25:22 EDT (New York time)\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
>ICS: date\015\012
<ICS: Sun Apr 04 19:28:22 EDT (New York time)\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
>ICS: date\015\012
<ICS: Sun Apr 04 19:31:22 EDT (New York time)\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
>ICS: date\015\012
<ICS: Sun Apr 04 19:34:22 EDT (New York time)\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
>ICS: date\015\012
<ICS: Sun Apr 04 19:37:22 EDT (New York time)\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
>ICS: date\015\012
<ICS: Sun Apr 04 19:40:22 EDT (New York time)\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
>ICS: date\015\012
<ICS: Sun Apr 04 19:43:22 EDT (New York time)\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
ForwardInner(1), current 0, forward 0
>ICS: games crafty\015\012
<ICS: crafty is not playing or examining a game.\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
>ICS: rematch\015\012
<ICS: Issuing: ArasanX (2563) crafty (2638) rated Standard 15 3\015\012Estimated rating changes: Loss: -13 Draw: +3 Win: +19\015\012crafty is in the computer list.\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
<ICS: \015\012Creating: ArasanX (2563) crafty (2638) rated Standard 15 3\015\012\007crafty accepts your challenge.\015\012"Seeking" ad #355 removed.\015\012"Seeking" ad #443 removed.\015\012{Game 712 (crafty vs. ArasanX) Creating rated standard match.} *\015\012\015\012<12> rnbqkbnr pppppppp -------- -------- -------- -------- PPPPPPPP RNBQKBNR W -1 1 1 1 1 0 712 crafty ArasanX -1 15 3 39 39 900 900 1 none (0:00) none 1\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
Ratings from 'Creating:' ArasanX 2563, crafty 2638
recognized 'rated standard match.' (-1) as variant normal
Parsing board: rnbqkbnr pppppppp -------- -------- -------- -------- PPPPPPPP RNBQKBNR W -1 1 1 1 1 0 712 crafty ArasanX -1 15 3 39 39 900 900 1 none (0:00) none 1

recognized 'ICS rated standard match' (-1) as variant normal
ParseBoard says variant = 'ICS rated standard match'
recognized as normal
Remembered ratings: W 2638, B 2563
load 8x8 board
4144499 >first : level 0 15 3
4144499 >first : computer
4144499 >first : name crafty
4144499 >first : rating 2563 2638
nps: w=-1, b=-1
Display title 'crafty (39) vs. ArasanX (39) {15 3}, gameInfo.variant = 0'
4144539 <first : # got cmd (main): level 0 15 3
4144539 <first : # do_command: level 0 15 3
4144539 <first : # in do_pending, list size=0
4144539 <first : # out of do_pending, list size=0
4144539 <first : # got cmd (main): computer
4144539 <first : # do_command: computer
4144539 <first : # in do_pending, list size=0
4144539 <first : # out of do_pending, list size=0
4144539 <first : # got cmd (main): name crafty
4144539 <first : # do_command: name crafty
4144539 <first : # in do_pending, list size=0
4144539 <first : # out of do_pending, list size=0
4144539 <first : # got cmd (main): rating 2563 2638
4144539 <first : # do_command: rating 2563 2638
4144539 <first : # rating = rating 2563 2638
4144539 <first : # in do_pending, list size=0
4144539 <first : # out of do_pending, list size=0
<ICS: \015\012crafty(C) kibitzes: Hello from Crafty v23.3! (8 cpus)\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
<ICS: \007\015\012<12> rnbqkbnr pppppppp -------- -------- ----P--- -------- PPPP-PPP RNBQKBNR B 4 1 1 1 1 0 712 crafty ArasanX 1 15 3 39 39 903 900 1 P/e2-e4 (0:00) e4 1\015\012aics%
ics input 0, castling = 7 0 4 7 0 4
Parsing board: rnbqkbnr pppppppp -------- -------- ----P--- -------- PPPP-PPP RNBQKBNR B 4 1 1 1 1 0 712 crafty ArasanX 1 15 3 39 39 903 900 1 P/e2-e4 (0:00) e4 1

load 8x8 board
parseboard 1, castling = 7 0 4 7 0 4
accepted move e4 from ICS, parse it.
moveNum = 1
board = 0-8 x 8
move to parse: e4
Disambiguate in: 0(4,-1)-(4,3) = 0 (-)
Disambiguate out: 0(4,1)-(4,3) = 0 (-)
CoordsToAlgebraic, piece=0 (4,1)-(4,3) -
7 0 4 7 0 4 Legality test? e2e4
movetype=33, promochar=0=-
MateTest: K=1, my=16, his=16
Move parsed to 'e4 (0:00)'
time odds: 1.000000 1.000000
4145612 >first : time 90000
4145612 >first : otim 90300
book hit = (NULL)
4145612 >first : usermove 4145612 >first : e4
AnimateMove: piece 0 slides from 4,1 to 4,3
nps: w=-1, b=-1
Display title 'crafty (39) vs. ArasanX (39) {15 3}, gameInfo.variant = 0'
4145704 <first : # got cmd (main): time 90000
4145704 <first : # do_command: time 90000
4145704 <first : # in do_pending, list size=0
4145704 <first : # out of do_pending, list size=0
4145704 <first : # got cmd (main): otim 90300
4145704 <first : # do_command: otim 90300
4145704 <first : # in do_pending, list size=0
4145704 <first : # out of do_pending, list size=0
4145704 <first : # got cmd (main): usermove e4
4145704 <first : # do_command: usermove e4
4145704 <first : # move text = e4
4145704 <first : # got move: e4
4145704 <first : # execute_move: e2-e4
4145704 <first : # in search()
4145704 <first : tellics kibitz book moves: (e5 92, c5 82, e6 52, c6 42, Nf6 32, d6 15, g6 14), choosing c5
>ICS: kibitz book moves: (e5 92, c5 82, e6 52, c6 42, Nf6 32, d6 15, g6 14), choosing c5
>ICS: \015\012
4145704 <first : # state = 0
4145704 <first : # game_end = 0
4145704 <first : move c7c5
Undoing extra move from first, gameMode 13
4145704 >first : undo

[H.G.Muller]

Arasan sends a lot (all decently commented out with #), but I cannot find a pong in the debug output you posted. XBoard does send it a ping 2 after the game ends, and a ping 3 after new. I guess that as long as it did not receive the corresponding pong commands from the engine, it will assume any moves it gets were still moves from the previous game.

[jdart]

Thanks, I'll look into that.

--Jon