Bot doesn't play the move supplied by the engine through UCI

[arvyy]

Engine responded with a move, but it wasn't played, resulting in bot losing on time. In logs I see

2024-01-21 18:33:36,435 chess.engine (engine.py:1062) DEBUG <UciProtocol (pid=69018)>: << position startpos moves e2e4 a7a5 f1c4 a5a4 g1f3 a8a7 d2d3 a7a5 c1d2
2024-01-21 18:33:36,436 chess.engine (engine.py:1062) DEBUG <UciProtocol (pid=69018)>: << go wtime 866320 btime 852039 winc 14000 binc 14000 depth 5 movetime 2000
2024-01-21 18:33:48,442 chess.engine (engine.py:1062) DEBUG <UciProtocol (pid=69018)>: << stop
2024-01-21 18:33:48,442 chess.engine (engine.py:1088) DEBUG <UciProtocol (pid=69018)>: >> bestmove a5c5
2024-01-21 18:37:24,698 __main__ (lichess-bot.py:370) DEBUG Event: {'type': 'correspondence_ping'}
2024-01-21 18:38:57,491 __mp_main__ (lichess-bot.py:697) DEBUG Game state: {'type': 'chatLine', 'room': 'player', 'username': 'tzar_bomba', 'text': '!help'}
2024-01-21 18:38:57,492 lib.conversation (conversation.py:42) INFO *** https://lichess.org/ysYc4BEr/black [player] tzar_bomba: !help
2024-01-21 18:38:57,492 lib.conversation (conversation.py:83) INFO *** https://lichess.org/ysYc4BEr/black [player] arvyy_bot: Supported commands: !wait (wait a minute for my first move), !name, !howto, !eval, !queue
2024-01-21 18:38:57,493 urllib3.connectionpool (connectionpool.py:292) DEBUG Resetting dropped connection: lichess.org

so the a5c5 was communicated, but it was never played, despite bot being responsive for chat commands https://lichess.org/ysYc4BEr . Using latest master commit (8deb03cb6b6e10697ae81ca2900902a3bd8e9db0)

[MarkZH]

Can you post the entire log of that session?

[arvyy]

sorry, looks like the log doesn't go that back far

one thing I noticed, is that engine disrespected movetime parameter by a lot (my engine is still pretty primitive and doesn't obey all limits), perhaps related

[AttackingOrDefending]

You got a Resetting dropped connection: lichess.org 2 milliseconds after the chat logs, so maybe it reset the connection before the receiving the chat message but the logs were in a different order.

In the requests docs, it suggests setting stream to False when using keep-alive, so that could have also played a role.

We can possibly create a pinger, that pings lichess every minute to not drop the connection.

[MarkZH]

After @arvyy mentioned the engine overshooting the movetime paramter, I went looking through the python-chess library code. I was confused about why the engine was sent a stop command after 12 seconds. When the play() method for an engine is called, there is a default timeout set for movetime plus 10 seconds (see here). That's why there's a stop command 12 seconds after the go command. If you remove the uci_options: go_commands: movetime parameter from your config file, this problem should no longer happen.

[MarkZH]

One more thing: the move was never sent to lichess because the task that waits for the engine to choose a move was cancelled after the timeout expired. I don't think we should change the timeout because its purpose is to not let misbehaving engines tie up an entire process.

[arvyy]

One more thing: the move was never sent to lichess because the task that waits for the engine to choose a move was cancelled after the timeout expired. I don't think we should change the timeout because its purpose is to not let misbehaving engines tie up an entire process.

I suppose the sensible resolution then, is to make bot forfeit the match on timeout (instead of losing on time) and maybe log a corresponding message

[MarkZH]

@arvyy I just submitted a pull request that should handle this issue. It doesn't cause the bot to resign, but it does shut down and restart the bot to allow it to attempt to finish the game. It also shows the error to the user on the console and in the log. Please try it and let me know if it works for you.