Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Exception raise when game is draw #379

Closed
pascalgeo opened this issue Mar 16, 2019 · 14 comments
Closed

Exception raise when game is draw #379

pascalgeo opened this issue Mar 16, 2019 · 14 comments
Labels
bug engine Chess engine integration

Comments

@pascalgeo
Copy link

pascalgeo commented Mar 16, 2019

When making a match engine, I get a raised exception when the game is a draw :

Exception in callback EngineProtocol.pipe_data_received(1, b'you play bo...Drawn game}\n')
handle: <Handle EngineProtocol.pipe_data_received(1, b'you play bo...Drawn game}\n')>
Traceback (most recent call last):
  File "/usr/lib/python3.5/asyncio/events.py", line 126, in _run
    self._callback(*self._args)
  File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 602, in pipe_data_received
    self._line_received(line)
  File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 615, in _line_received
    self.command._line_received(self, line)
  File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 869, in _line_received
    self.line_received(engine, line)
  File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 1716, in line_received
    self._move(engine, line.split(" ", 1)[1])
  File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 1748, in _move
    self.result.set_result(PlayResult(move, None, self.info, self.draw_offered))
  File "/usr/lib/python3.5/asyncio/futures.py", line 348, in set_result
    raise InvalidStateError('{}: {!r}'.format(self._state, self))
asyncio.futures.InvalidStateError: FINISHED: <Future finished result=<PlayResult a...ffered=False)>>
Traceback (most recent call last):
  File "./tournament.py", line 96, in <module>
    board.push(result.move)
  File "/home/pascal/.local/lib/python3.5/site-packages/chess/__init__.py", line 1942, in push
    move = self._to_chess960(move)
  File "/home/pascal/.local/lib/python3.5/site-packages/chess/__init__.py", line 3318, in _to_chess960
    if move.from_square == E1 and self.kings & BB_E1:
AttributeError: 'NoneType' object has no attribute 'from_square'
@niklasf niklasf added bug engine Chess engine integration labels Mar 16, 2019
@niklasf
Copy link
Owner

niklasf commented Mar 16, 2019

Intresting. I guess the second part is expected for board.push(None).

However the first shouldn't happen, of course. Which engine did you use? Or alternatively, import logging; logging.basicConfig(level=logging.DEBUG) would be useful to get an overview of the engine output that python-chess couldn't handle.

@pascalgeo
Copy link
Author

It is with Stockfish (UCI) vs Phalanx (xboard). I get some exceptions like the one below, without being the side effect of a first exception. So maybe Phalanx misbehaves as an xboard engine, I will try to track this down.

File "./tournament.py", line 96, in
board.push(result.move)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/init.py", line 1942, in push
move = self._to_chess960(move)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/init.py", line 3318, in _to_chess960
if move.from_square == E1 and self.kings & BB_E1:
AttributeError: 'NoneType' object has no attribute 'from_square'

@niklasf
Copy link
Owner

niklasf commented Mar 16, 2019

Some speculation, looking at the source code of Phalanx: In some cases it prints move back, which python-chess might confuse with an actual move.

/* COMMAND: remove (xboard) */                                                  
»»»»if( strncmp( Inp, "remove", 6 ) == 0 )                                      
»»»»{                                                                           
»»»»»»»»if( Flag.ponder >= 2 ) { Abort = 1; return 0; }                         
»»»»»»»»if( Counter > 1 )                                                       
»»»»»»»»{                                                                       
»»»»»»»»»»»»undo_move( & G[Counter-1].m );                                      
»»»»»»»»»»»»undo_move( & G[Counter-1].m );                                      
»»»»»»»»»»»»if(Flag.xboard<2) puts("move back");                                
»»»»»»»»»»»»if( Flag.machine_color != 0 )                                       
»»»»»»»»»»»»Flag.machine_color = enemy(Color);                                  
»»»»»»»»}                                                                       
»»»»»»»»else puts("cannot remove");                                             
»»»»»»»»Inp[0]='\0'; return 1;                                                  
»»»»}  

@pascalgeo
Copy link
Author

I don't think it is the cause. There is no reason a 'remove' command is sent in my program.
I think there is not enough LOGGER.debug calls in xboard engine code, I added some to help pinning down the error.

@niklasf
Copy link
Owner

niklasf commented Mar 16, 2019

Are you playing multiple games back to back, by any chance? If so, remove could be used to reset the board, because by default python-chess assumes it all belongs to the same game. engine.play(..., game="game id") would be a way to prevent that.

@pascalgeo
Copy link
Author

I instantiate a new Board for every game, so I doubt this is it.

@niklasf
Copy link
Owner

niklasf commented Mar 16, 2019

The board object isn't used to determine this, only the game argument. But yeah ... maybe it's completely unrelated. (In that case it would be a second bug).

Edit: Never mind, you're right. Flag.xboard should be 2 in xboard mode anyway.

@pascalgeo
Copy link
Author

Here is output preceding an error (Phalanx playing against itself):

DEBUG:chess.engine:<XBoardProtocol (pid=21012)>: << otim 7031
DEBUG:chess.engine:<XBoardProtocol (pid=21012)>: << time 6780
DEBUG:chess.engine:<XBoardProtocol (pid=21012)>: << nopost
DEBUG:chess.engine:<XBoardProtocol (pid=21012)>: << easy
DEBUG:chess.engine:<XBoardProtocol (pid=21012)>: << go
DEBUG:chess.engine:<XBoardProtocol (pid=21012)>: >> you play both
WARNING:chess.engine:<XBoardProtocol (pid=21012)>: Unexpected engine output: you play both
DEBUG:chess.engine:<XBoardProtocol (pid=21012)>: >> level: 25 moves in 1:07, increment 0 seconds
WARNING:chess.engine:<XBoardProtocol (pid=21012)>: Unexpected engine output: level: 25 moves in 1:07, increment 0 seconds
DEBUG:chess.engine:<XBoardProtocol (pid=21012)>: >> post off
WARNING:chess.engine:<XBoardProtocol (pid=21012)>: Unexpected engine output: post off
DEBUG:chess.engine:<XBoardProtocol (pid=21012)>: >> pondering off
WARNING:chess.engine:<XBoardProtocol (pid=21012)>: Unexpected engine output: pondering off
DEBUG:chess.engine:<XBoardProtocol (pid=21012)>: >> move b2b3
DEBUG:chess.engine:<XBoardProtocol (pid=21012)>: >> 1/2-1/2 {Drawn game}
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: << force
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: << b2b3
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: << level 24 1:10 0
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: << time 7031
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: << otim 6441
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: << nopost
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: << easy
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: << go
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: >> you play both
WARNING:chess.engine:<XBoardProtocol (pid=21010)>: Unexpected engine output: you play both
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: >> 1/2-1/2 {Drawn game}
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: >> level: 24 moves in 1:10, increment 0 seconds
WARNING:chess.engine:<XBoardProtocol (pid=21010)>: Unexpected engine output: level: 24 moves in 1:10, increment 0 seconds
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: >> post off
WARNING:chess.engine:<XBoardProtocol (pid=21010)>: Unexpected engine output: post off
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: >> pondering off
WARNING:chess.engine:<XBoardProtocol (pid=21010)>: Unexpected engine output: pondering off
Traceback (most recent call last):
File "./tournament.py", line 99, in
board.push(result.move)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/init.py", line 1942, in push
move = self._to_chess960(move)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/init.py", line 3318, in _to_chess960
if move.from_square == E1 and self.kings & BB_E1:
AttributeError: 'NoneType' object has no attribute 'from_square'
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: >> move f3f2
DEBUG:chess.engine:<XBoardProtocol (pid=21010)>: >> 1/2-1/2 {Drawn game}

Please note that I think the bug raises when a draw is met. The code seems to try to handle a move board.push(result.move) before it is received

move f3f2

@pascalgeo
Copy link
Author

I switched to Crafty to check with a reliable engine. Here is an error I got. To resign is handled in engine.py at line 1723, I don't know why this crashes.

DEBUG:chess.engine:<XBoardProtocol (pid=26359)>: >> move Qd6+
white_clock 47.091694000000004 black_clock 44.27297299999999 remaining_moves 29
DEBUG:chess.engine:<XBoardProtocol (pid=26361)>: << force
DEBUG:chess.engine:<XBoardProtocol (pid=26361)>: << c5d6
DEBUG:chess.engine:<XBoardProtocol (pid=26361)>: << level 29 0:44 0
DEBUG:chess.engine:<XBoardProtocol (pid=26361)>: << otim 4709
DEBUG:chess.engine:<XBoardProtocol (pid=26361)>: << time 4427
DEBUG:chess.engine:<XBoardProtocol (pid=26361)>: << nopost
DEBUG:chess.engine:<XBoardProtocol (pid=26361)>: << easy
DEBUG:chess.engine:<XBoardProtocol (pid=26361)>: << go
DEBUG:chess.engine:<XBoardProtocol (pid=26361)>: >> resign
DEBUG:chess.engine:<XBoardProtocol (pid=26361)>: >> 1-0 {Black resigns}
WARNING:chess.engine:<XBoardProtocol (pid=26361)>: Unexpected engine output: 1-0 {Black resigns}
DEBUG:chess.engine:<XBoardProtocol (pid=26361)>: >> move Ke8
ERROR:asyncio:Exception in callback EngineProtocol.pipe_data_received(1, b'resign\n\x0...}\nmove Ke8\n')
handle: <Handle EngineProtocol.pipe_data_received(1, b'resign\n\x0...}\nmove Ke8\n')>
Traceback (most recent call last):
File "/usr/lib/python3.5/asyncio/events.py", line 126, in _run
self._callback(*self._args)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 602, in pipe_data_received
self._line_received(line)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 615, in _line_received
self.command._line_received(self, line)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 869, in _line_received
self.line_received(engine, line)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 1716, in line_received
self._move(engine, line.split(" ", 1)[1])
File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 1748, in _move
self.result.set_result(PlayResult(move, None, self.info, self.draw_offered))
File "/usr/lib/python3.5/asyncio/futures.py", line 348, in set_result
raise InvalidStateError('{}: {!r}'.format(self._state, self))
asyncio.futures.InvalidStateError: FINISHED: <Future finished exception=EngineError('xboard engine resigned',)>
Traceback (most recent call last):
File "./tournament.py", line 94, in
result = eng.play(board, lim)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 2220, in play
return future.result()
File "/usr/lib/python3.5/concurrent/futures/_base.py", line 405, in result
return self.__get_result()
File "/usr/lib/python3.5/concurrent/futures/_base.py", line 357, in __get_result
raise self._exception
File "/usr/lib/python3.5/asyncio/tasks.py", line 241, in _step
result = coro.throw(exc)
File "/usr/lib/python3.5/asyncio/tasks.py", line 381, in wait_for
return (yield from fut)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 1777, in play
return (yield from self.communicate(Command))
File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 654, in communicate
return (yield from command.result)
File "/usr/lib/python3.5/asyncio/futures.py", line 380, in iter
yield self # This tells Task to wait for completion.
File "/usr/lib/python3.5/asyncio/tasks.py", line 304, in _wakeup
future.result()
File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
raise self._exception
chess.engine.EngineError: xboard engine resigned

@pascalgeo pascalgeo reopened this Mar 17, 2019
@pascalgeo
Copy link
Author

Maybe I should have opened a new issue for the 'resign' case, but for the previous one, the issue is still present (python-chess version 27.2). See below, Stockfish vs Phalanx :

DEBUG:chess.engine:<UciProtocol (pid=26688)>: >> info depth 127 seldepth 2 multipv 1 score cp 0 nodes 7366 nps 199081 tbhits 0 time 37 pv e5h2
DEBUG:chess.engine:<UciProtocol (pid=26688)>: >> bestmove e5a1
white_clock 11.561839000000006 black_clock 88.59437399999997 remaining_moves 12
DEBUG:chess.engine:<XBoardProtocol (pid=26686)>: << force
DEBUG:chess.engine:<XBoardProtocol (pid=26686)>: << e5a1
DEBUG:chess.engine:<XBoardProtocol (pid=26686)>: << level 12 0:11 0
DEBUG:chess.engine:<XBoardProtocol (pid=26686)>: << time 1156
DEBUG:chess.engine:<XBoardProtocol (pid=26686)>: << otim 8859
DEBUG:chess.engine:<XBoardProtocol (pid=26686)>: << nopost
DEBUG:chess.engine:<XBoardProtocol (pid=26686)>: << easy
DEBUG:chess.engine:<XBoardProtocol (pid=26686)>: << go
DEBUG:chess.engine:<XBoardProtocol (pid=26686)>: >> you play both
WARNING:chess.engine:<XBoardProtocol (pid=26686)>: Unexpected engine output: you play both
DEBUG:chess.engine:<XBoardProtocol (pid=26686)>: >> 1/2-1/2 {Drawn game}
DEBUG:chess.engine:<XBoardProtocol (pid=26686)>: >> level: 12 moves in 0:11, increment 0 seconds
WARNING:chess.engine:<XBoardProtocol (pid=26686)>: Unexpected engine output: level: 12 moves in 0:11, increment 0 seconds
DEBUG:chess.engine:<XBoardProtocol (pid=26686)>: >> post off
WARNING:chess.engine:<XBoardProtocol (pid=26686)>: Unexpected engine output: post off
DEBUG:chess.engine:<XBoardProtocol (pid=26686)>: >> pondering off
WARNING:chess.engine:<XBoardProtocol (pid=26686)>: Unexpected engine output: pondering off
DEBUG:chess.engine:<XBoardProtocol (pid=26686)>: >> move c6b5
ERROR:asyncio:Exception in callback EngineProtocol.pipe_data_received(1, b'you play bo...Drawn game}\n')
handle: <Handle EngineProtocol.pipe_data_received(1, b'you play bo...Drawn game}\n')>
Traceback (most recent call last):
File "/usr/lib/python3.5/asyncio/events.py", line 126, in _run
self._callback(*self._args)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 602, in pipe_data_received
self._line_received(line)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 615, in _line_received
self.command._line_received(self, line)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 869, in _line_received
self.line_received(engine, line)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 1716, in line_received
self._move(engine, line.split(" ", 1)[1])
File "/home/pascal/.local/lib/python3.5/site-packages/chess/engine.py", line 1748, in _move
self.result.set_result(PlayResult(move, None, self.info, self.draw_offered))
File "/usr/lib/python3.5/asyncio/futures.py", line 348, in set_result
raise InvalidStateError('{}: {!r}'.format(self._state, self))
asyncio.futures.InvalidStateError: FINISHED: <Future finished result=>
Traceback (most recent call last):
File "./tournament.py", line 100, in
board.push(result.move)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/init.py", line 1942, in push
move = self._to_chess960(move)
File "/home/pascal/.local/lib/python3.5/site-packages/chess/init.py", line 3318, in _to_chess960
if move.from_square == E1 and self.kings & BB_E1:
AttributeError: 'NoneType' object has no attribute 'from_square'

@pascalgeo
Copy link
Author

I may have an explanation : InvalidStateError means set_result() was already called for the Future.
First the received line '1/2-1/2 {Drawn game}' is handled at line 1726 with the following :

                elif line.startswith("1-0") or line.startswith("0-1") or line.startswith("1/2-1/2"):
                    if not self.result.done():
                        self.result.set_result(PlayResult(None, None, self.info, self.draw_offered))
                    self.end(engine)

And then the received line 'move c6b5' is handled and triggers at line 1748
self.result.set_result(PlayResult(move, None, self.info, self.draw_offered))
without the protection if not self.result.done():. If the Future is the same, it explains the exception raised.

@niklasf
Copy link
Owner

niklasf commented Mar 17, 2019

Thanks, these logs help a lot. So apparently engines declare the game as over (1/2-1/2, resign) but then send a move anyway 😢.

Not so important: Is this even valid according to the spec? It doesn't make sense to me, and indeed resign or 1/2-1/2 will always be the final output in the sample implementation (Appendix C).

Either way we have to deal with it. That's problematic, because we don't really know when the command is complete. Will a move come, or not? Maybe an extra ping/pong cycle is required to make sure.

@pascalgeo
Copy link
Author

pascalgeo commented Mar 17, 2019

I read two versions of the spec, and sending a move after a result should not be allowed, this is non sense (and confirmed by the code in appendix C). I looked quickly at Phalanx code and maybe it is buggy, sending an extra move. The idea is to harden the code so that self.result.set_result() is not called twice for an unique Future; once you are sure a game is over, you may dismiss everything else from the engine.
Note that Crafty triggers the same exception :

asyncio.futures.InvalidStateError: FINISHED: <Future finished exception=EngineError('xboard engine resigned',)

Which means Future result was set twice after a game ended by a draw.

@niklasf
Copy link
Owner

niklasf commented Mar 20, 2019

Ok ... it wasn't as simple as ignoring the extra move (because it could slip over to the next communication, or get engine.board out of sync), but I think I have a workaround. It costs one extra ping/pong cycle.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug engine Chess engine integration
Projects
None yet
Development

No branches or pull requests

2 participants