Engine sent invalid ponder move

[josephbima]

Traceback (most recent call last):
   File "/home/bimajenie/.local/lib/python3.6/site-packages/chess/engine.py", line 1483, in _parse_uci_bestmove
 ponder = board.parse_uci(tokens[2])
  File "/home/bimajenie/.local/lib/python3.6/site-packages/chess/__init__.py", line 2880, in parse_uci
 raise ValueError(f"illegal uci: {uci!r} in {self.fen()}")
 <UciProtocol (pid=31621)>: Unexpected engine output:

Hi, I am getting this error while running concurrent games. It comes and go, becoming a problem in every 20-50 game. Pondering is disabled, and this is how I'm getting the best move:

board = chess.Board(fen)
result = engine.play(board, chess.engine.Limit(time=0.1,nodes=5)) # Play a move with time limit 0.1s
best_move = result.move
board.push(best_move)

[josephbima]

So far I haven't been able to reproduce the problem

[niklasf]

Which engine is this?

[niklasf]

Also it looks like some useful lines of the console output are cut off. Please provide a couple lines ahead and after your snippet, if you still have them.

[josephbima]

This is the stockfish 11 engine for linux. The weird thing is that the output cut off in the last line of the error I put. I did miss this line at the start though engine sent invalid ponder move. But aside that, this is the entire error message.

engine sent invalid ponder move
2020-06-10T16:14:16: Traceback (most recent call last):
2020-06-10T16:14:16:   File "/home/bimajenie/.local/lib/python3.6/site-packages/chess/engine.py", line 1483, in _parse_uci_bestmove
2020-06-10T16:14:16:     ponder = board.parse_uci(tokens[2])
2020-06-10T16:14:16:   File "/home/bimajenie/.local/lib/python3.6/site-packages/chess/__init__.py", line 2880, in parse_uci
2020-06-10T16:14:16:     raise ValueError(f"illegal uci: {uci!r} in {self.fen()}")
2020-06-10T16:14:16:
2020-06-11T01:14:46: <UciProtocol (pid=31621)>: Unexpected engine output:

[niklasf]

Thanks. What do you mean by running concurrent games?

[josephbima]

I am making a platform for users to play against a chess "computer" using stockfish. So there can be 5-20 users hitting the server and playing the game at the same time. It is already in production and once in a while I am getting that error.

[niklasf]

A couple more questions:

• Are they concurrently using the same engine instance?
• Surprisingly the ValueError itself is not included in the error output. Can you please try logging the position for context, or (if possible) enable debug logging for context: https://python-chess.readthedocs.io/en/latest/engine.html#logging

[hasnul]

I believe I'm getting possibly the same or related error. Engine is Houdini 1.5 w32.

Here is the log:

DEBUG:chess.engine:<UciProtocol (pid=None)>: >> info multipv 1 depth 28 seldepth 31 score cp 0  time 91 nodes 385047 nps 4231000 tbhits 0 hashfull 2 pv b4a3
DEBUG:chess.engine:<UciProtocol (pid=None)>: >> bestmove b4a3 ponder NULL
ERROR:chess.engine:engine sent invalid ponder move
Traceback (most recent call last):
  File "/home/hasnul/github/picochess/expts/2/venv/lib/python3.8/site-packages/chess/engine.py", line 1483, in _parse_uci_bestmove
    ponder = board.parse_uci(tokens[2])
  File "/home/hasnul/github/picochess/expts/2/venv/lib/python3.8/site-packages/chess/__init__.py", line 2871, in parse_uci
    move = Move.from_uci(uci)
  File "/home/hasnul/github/picochess/expts/2/venv/lib/python3.8/site-packages/chess/__init__.py", line 509, in from_uci
    from_square = SQUARE_NAMES.index(uci[0:2])
ValueError: 'NU' is not in list
DEBUG:chess.engine:<UciProtocol (pid=None)>: << stop

ponder NULL?

[niklasf]

Wierd ... the spec says not to send ponder at all, then. But it's easy to work around this, so I did.

However I am fairly certain that Stockfish never sends something like that, so it must be a separate issue.

[josephbima]

A couple more questions:

• Are they concurrently using the same engine instance?
• Surprisingly the ValueError itself is not included in the error output. Can you please try logging the position for context, or (if possible) enable debug logging for context: https://python-chess.readthedocs.io/en/latest/engine.html#logging

They are using the same engine instance. I tried making sure that the move is never None but that seems to not fix the problem. I have enabled logging and I will post more if I see the error come up again.

edit: Just curious, is it better to use the same engine and have it sit there to evaluate different moves or create a new engine instance every time a move needs to be reviewed?

[bautoff]

I almost always get this issue when I run more than 20-25k evaluations on the same engine instance.

For example, last time runing engine.analyse(board, chess.engine.Limit(depth=depth), multipv=1)on the board 'R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61' I got a whole bunch of warnings starting with :

exception parsing pv from info: 'depth 1 seldepth 1 multipv 1 score cp -242 nodes 28 nps 28000 tbhits 0 time 1 pv h3g2', position at root: R7/8/2p5/1p6/4k3/3n3K/p5r1/8 b - - 5 60
Traceback (most recent call last):
  File "/home/xxx/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/xxx/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/xxx/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'h3g2' in R7/8/2p5/1p6/4k3/3n3K/p5r1/8 b - - 5 60
exception parsing pv from info: 'depth 2 seldepth 2 multipv 1 score cp -242 nodes 53 nps 53000 tbhits 0 time 1 pv h3g2 d3c1', position at root: R7/8/2p5/1p6/4k3/3n3K/p5r1/8 b - - 5 60
Traceback (most recent call last):
  File "/home/xxx/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))

and so on…

The resulting ev is:

[{'depth': 6,
  'seldepth': 6,
  'multipv': 1,
  'score': PovScore(Cp(-242), WHITE),
  'nodes': 215,
  'nps': 215000,
  'tbhits': 0,
  'time': 0.001,
  'pv': []}]

[niklasf]

@bautoff Is this Stockfish and can you please record which position was sent to the engine (or even better, the entire log)? Otherwise it's impossible to tell if this is a bug in the engine or in python-chess. ValueError: illegal uci: 'h3g2' in R7/8/2p5/1p6/4k3/3n3K/p5r1/8 b - - 5 60 seems consistent, at least.

[bautoff]

Yes, Stockfish.

It was trying to evaluate R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61. The last move was Move.from_uci('d3f4').

exception parsing pv from info: 'depth 1 seldepth 1 multipv 1 score cp -242 nodes 28 nps 14000 tbhits 0 time 2 pv h3g2', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'h3g2' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 2 seldepth 2 multipv 1 score cp -242 nodes 52 nps 26000 tbhits 0 time 2 pv h3g2 d3c1', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'h3g2' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 2 seldepth 2 multipv 1 score cp -242 nodes 52 nps 26000 tbhits 0 time 2 pv h3g2 d3c1', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'd3c1' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 3 seldepth 3 multipv 1 score cp -242 nodes 80 nps 40000 tbhits 0 time 2 pv h3g2 d3c1 g2f2', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'h3g2' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 3 seldepth 3 multipv 1 score cp -242 nodes 80 nps 40000 tbhits 0 time 2 pv h3g2 d3c1 g2f2', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'd3c1' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 3 seldepth 3 multipv 1 score cp -242 nodes 80 nps 40000 tbhits 0 time 2 pv h3g2 d3c1 g2f2', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'g2f2' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 4 seldepth 4 multipv 1 score cp -242 nodes 112 nps 56000 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'h3g2' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 4 seldepth 4 multipv 1 score cp -242 nodes 112 nps 56000 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'd3c1' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 4 seldepth 4 multipv 1 score cp -242 nodes 112 nps 56000 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'g2f2' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 4 seldepth 4 multipv 1 score cp -242 nodes 112 nps 56000 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'e4e5' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 5 seldepth 5 multipv 1 score cp -242 nodes 154 nps 77000 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5 f2e3', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'h3g2' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 5 seldepth 5 multipv 1 score cp -242 nodes 154 nps 77000 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5 f2e3', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'd3c1' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 5 seldepth 5 multipv 1 score cp -242 nodes 154 nps 77000 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5 f2e3', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'g2f2' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 5 seldepth 5 multipv 1 score cp -242 nodes 154 nps 77000 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5 f2e3', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'e4e5' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 5 seldepth 5 multipv 1 score cp -242 nodes 154 nps 77000 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5 f2e3', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'f2e3' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 6 seldepth 6 multipv 1 score cp -242 nodes 219 nps 109500 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5 f2e3 b5b4', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'h3g2' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 6 seldepth 6 multipv 1 score cp -242 nodes 219 nps 109500 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5 f2e3 b5b4', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'd3c1' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 6 seldepth 6 multipv 1 score cp -242 nodes 219 nps 109500 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5 f2e3 b5b4', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'g2f2' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 6 seldepth 6 multipv 1 score cp -242 nodes 219 nps 109500 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5 f2e3 b5b4', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'e4e5' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 6 seldepth 6 multipv 1 score cp -242 nodes 219 nps 109500 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5 f2e3 b5b4', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'f2e3' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
exception parsing pv from info: 'depth 6 seldepth 6 multipv 1 score cp -242 nodes 219 nps 109500 tbhits 0 time 2 pv h3g2 d3c1 g2f2 e4e5 f2e3 b5b4', position at root: R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61
Traceback (most recent call last):
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/engine.py", line 1449, in _parse_uci_info
    pv.append(board.push_uci(token))
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2833, in push_uci
    move = self.parse_uci(uci)
  File "/home/dennis/anaconda3/lib/python3.7/site-packages/chess/__init__.py", line 2820, in parse_uci
    raise ValueError("illegal uci: {!r} in {}".format(uci, self.fen()))
ValueError: illegal uci: 'b5b4' in R7/8/2p5/1p6/4kn2/7K/p5r1/8 w - - 6 61

[bautoff]

It happens quite often. I think you can reproduce it with any database, maybe even with the same position, running evaluations 30k+ times.

[niklasf]

Thanks. Then, assuming python-chess properly communicated that setup, depth 1 seldepth 1 multipv 1 score cp -242 nodes 28 nps 14000 tbhits 0 time 2 pv h3g2 is indeed invalid, because Kxg2 is not legal.

[niklasf]

I tried the following, but did not run into any error:

import chess
import chess.engine
import logging

logging.basicConfig(level=logging.INFO)

board = chess.Board("R7/8/2p5/1p6/4k3/3n3K/p5r1/8 b - - 5 60")
board.push_san("Nf4")

with chess.engine.SimpleEngine.popen_uci("stockfish") as engine:
    for i in range(100_000):
        engine.analyse(board, chess.engine.Limit(depth=4))
        if i % 1000 == 0:
            print(i)

This was with the official Stockfish 11 release.

What can I do to make it closer to your setup?

[bautoff]

My bad, sorry. Not 30k+ evaluations, of course. 30k+ games evaluating moves in each game.

What I was doing was simply this, nothing special:

    for i in range(n_games):                
        game = chess.pgn.read_game(pgn)      
        board = chess.Board()     

        for move in game.mainline_moves():
            board.push(move)
            if not board.is_game_over():
                evs = engine.analyse(board, chess.engine.Limit(depth=6), multipv=1)
                bestmove = evs[0].pv[0]

[niklasf]

Alright. Starting to run this now on a PGN from https://database.lichess.org/, and it will take a while to reach 30k+.

Meanwhile, in case this isn't enough to reproduce the issue ... the parameters give me some hope, because single-threaded Stockfish with depth limit is supposed to be deterministic.

• Are you also using Stockfish 11?
• Would you be able to share the concrete PGN (or at least the first 30k+ games of it), just to eliminate another variable?

[niklasf]

It's now way past 30k without any issue. I'll leave it running over night, but it looks like additional info may be necessary, in particular the PGN.

[bautoff]

I was using Stockfish 10.

Here's the database: https://send.firefox.com/download/7696f2861b83ab14/#imOTwS7G31Yiaz8c36Y8ZA

with open(source, encoding="iso-8859-1") as pgn:
    engine = chess.engine.SimpleEngine.popen_uci(stockfish)
    engine.configure({"Threads": 1, "Hash": 40})

    for i in range(500_000):                
        game = chess.pgn.read_game(pgn)      
        if "FEN" in game.headers:
            continue
        else:
            board = chess.Board()     

        for move in game.mainline_moves():
            board.push(move)
            if not board.is_game_over():
                evs = engine.analyse(board, chess.engine.Limit(depth=6), multipv=1)
                bestmove = evs[0].pv[0]

    engine.quit()

Got an error on i = 27295. But it really depends, sometimes it gets through the whole database like that one without any errors.

[niklasf]

Looks like I wasn't fast enough. The page says "This link is expired". I'll start another run with Stockfish 10 and your exact script in the meantime.

[bautoff]

https://send.firefox.com/download/21cde82b37f003d3/#-ZDuSPXWmUWdOZyW4RbneQ

[niklasf]

Awesome, thanks. Downloading now.

Btw, I noticed that you're probably not using the latest version (because evs[0].pv[0] should now be evs[0]["pv"][0]). That's probably not it, but if you have the time and resources, could you please upgrade to python-chess v0.31.2 and confirm that you can still reproduce the issue?

[bautoff]

Yes, I sometimes use the old version for my old scripts.

I tried the same database with the same script and got the error again on the same position.

I'll try it with v0.31later.

[bautoff]

The same error with Stockfish 11.

[niklasf]

This is the game:

[Event "AUS-ch U12"]                                                            
[Site "Adelaide"]                                                               
[Date "2009.01.04"]                                                             
[Round "4"]                                                                     
[White "Gowda, Akash"]                                                          
[Black "Bowditch, James"]                                                       
[Result "1/2-1/2"]                                                              
[BlackElo "861"]                                                                
[BlackTeamCountry "FRA"]                                                        
[ECO "D00"]                                                                     
[EventCountry "AUS"]                                                            
[EventDate "2009.01.02"]                                                        
[EventRounds "11"]                                                              
[EventType "swiss"]                                                             
[PlyCount "126"]                                                                
[Source "ChessBase"]                                                            
[SourceDate "2009.03.05"]                                                       
[WhiteTeamCountry "FRA"]                                                        

1. d4 d5 2. e3 Bf5 3. f4 e6 4. Nf3 Nf6 5. Bb5+ c6 6. Ba4 Qa5+ 7. Bd2 Qxa4 8. b3 Qb5 9. a4 Qb6 10. a5 Qb5 11. Nc3 Qb4 12. Na2 Qd6 13. Bb4 Qd7 14. Bxf8 Kxf8 15. O-O Ne4 16. Ne5 Qe7 17. Qe1 Qf6 18. Qb4+ Qe7 19. Qxe7+ Kxe7 20. c4 dxc4 21. bxc4 Nd2 22. Rfd1 f6 23. Rxd2 fxe5 24. dxe5 Na6 25. Re1 Nc5 26. Nc3 Rhd8 27. Rxd8 Rxd8 28. h3 Nb3 29. g4 Bd3 30. Kf2 Nxa5 31. f5 exf5 32. gxf5 Bxf5 33. Kg3 Nxc4 34. e4 Rd3+ 35. Kf4 Rxc3 36. Kxf5 g6+ 37. Kf4 h6 38. Rg1 Rxh3 39. Rxg6 Rh4+ 40. Kg3 Rxe4 41. Rg7+ Ke6 42. Rg6+ Kxe5 43. Rxh6 Re3+ 44. Kg4 a5 45. Rh5+ Ke4 46. Rh8 a4 47. Re8+ Ne5+ 48. Kg5 Rg3+ 49. Kf6 Rg6+ 50. Ke7 a3 51. Ra8 Rg7+ 52. Kf6 Rf7+ 53. Kg5 Nc4 54. Ra4 b5 55. Ra8 Rf2 56. Re8+ Ne5 57. Ra8 a2 58. Kh4 Rg2 59. Kh3 Nd3 60. -- Nf4+ 61. Kh4 Ng6+ 62. Kh3 Kf3 63. Rxa2 Rxa2 1/2-1/2

It has a null move (--) at move 60, which Stockfish does not understand. I'll add an assertion to identify this issue more quickly in the future. Thanks a lot for helping to debug this.

Unfortunately this also means it's unlikely to be the same issue as @josephbima was observing.

@josephbima: In this investigation I analyzed millions of positions without observing the "invalid ponder move" issue. Are you absolutely positive this was Stockfish 11 and not some other engine (e.g. Houdini as well)?

[bautoff]

Great. I thought that Stockfish does null move check, It didn't even come to my mind to check pgn for that. Thank you.

[josephbima]

Hi! Sorry been busy and not following the issue as much. The engine is 100% Stockfish 11 but I think my error might have been a version of Null moves. I purposely made my engine weak but it wasn't finding checkmate moves. So what I did was I loop through all the possible moves from board.legal_moves() and tested if one of them is a checkmate move. I think that has to be the problem since after removing that code snippet I haven't seen the error again. Maybe board.legal_move() sometimes spits out a Null move?

[niklasf]

Mhh ... board.legal_moves should never produce null moves. Did you weaken Stockfish by patching the engine or by setting parameters?

[josephbima]

I only weakened it using parameters. The engine : result = engine.play(board, chess.engine.Limit(time=0.1,nodes=3))

It was something like this:

for m in temp_board.legal_moves:
                temp_board.push(m)
                if temp_board.is_checkmate():
                    checkmate_found = True
                    checkmate_move = m
                    break
                temp_board.pop()

[niklasf]

Ok, thanks. That looks ok. I'll start another test run with extremely low limits like that. If it's inconclusive I guess I'll just close this issue until it's observed one more time.

[niklasf]

No issue seen in 20,000,000 played/analyzed positions.