lichess-bot-devs / lichess-bot

A bridge between Lichess bots and chess engines
GNU Affero General Public License v3.0
769 stars 449 forks source link

Aborted games with matchmaking #548

Closed ianagbip1oti closed 1 year ago

ianagbip1oti commented 2 years ago

Hi,

I'm seeing a pretty high number of aborted games since upgrading lichess-bot and enabling matchmaking. I'm not clear if all produce similar logs yet, but here is one example.

Game: https://lichess.org/xOUHjoyP/black Config: https://github.com/princesslana/princhess/blob/main/bin/config.yml

Logs

[08/21/22 01:23:26] INFO     Will challenge WillBoChessEngine matchmaking.py:133,
                             for a standard game.                               ,
                    DEBUG    https://lichess.org:443 "POST connectionpool.py:456,
                             /api/challenge/WillBoChessEng                      ,
                             ine HTTP/1.1" 200 None                             ,
                    INFO     Challenge id is xOUHjoyP.        matchmaking.py:135,
                    DEBUG    Event: {'type': 'challenge',     lichess-bot.py:211,
                             'challenge': {'id': 'xOUHjoyP',                    ,
                             'url':                                             ,
                             'https://lichess.org/xOUHjoyP',                    ,
                             'status': 'created',                               ,
                             'challenger': {'id':                               ,
                             'princhess_bot', 'name':                           ,
                             'princhess_bot', 'title': 'BOT',                   ,
                             'rating': 2066, 'online': True},                   ,
                             'destUser': {'id':                                 ,
                             'willbochessengine', 'name':                       ,
                             'WillBoChessEngine', 'title':                      ,
                             'BOT', 'rating': 2013, 'online':                   ,
                             True}, 'variant': {'key':                          ,
                             'standard', 'name': 'Standard',                    ,
                             'short': 'Std'}, 'rated': True,                    ,
                             'speed': 'blitz', 'timeControl':                   ,
                             {'type': 'clock', 'limit': 300,                    ,
                             'increment': 1, 'show': '5+1'},                    ,
                             'color': 'random', 'finalColor':                   ,
                             'black', 'perf': {'icon':                          ,
                             '\ue01d', 'name': 'Blitz'}},                       ,
                             'compat': {'bot': True, 'board':                   ,
                             True}}                                             ,
                    DEBUG    Event: {'type': 'gameStart',     lichess-bot.py:211,
                             'game': {'fullId':                                 ,
                             'xOUHjoyPQUnw', 'gameId':                          ,
                             'xOUHjoyP', 'fen':                                 ,
                             'rnbqkbnr/pppppppp/8/8/8/8/PPPPP                   ,
                             PPP/RNBQKBNR w KQkq - 0 1',                        ,
                             'color': 'black', 'lastMove':                      ,
                             '', 'source': 'friend',                            ,
                             'variant': {'key': 'standard',                     ,
                             'name': 'Standard'}, 'speed':                      ,
                             'blitz', 'perf': 'blitz',                          ,
                             'rated': True, 'hasMoved':                         ,
                             False, 'opponent': {'id':                          ,
                             'willbochessengine', 'username':                   ,
                             'BOT WillBoChessEngine',                           ,
                             'rating': 2013}, 'isMyTurn':                       ,
                             False, 'secondsLeft': 300,                         ,
                             'compat': {'bot': True, 'board':                   ,
                             True}, 'id': 'xOUHjoyP'}}                          ,
                    INFO     --- Process Used. Total Queued:  lichess-bot.py:182,
                             0. Total Used: 1                                   ,
[08/21/22 01:23:26] DEBUG    Starting new HTTPS           connectionpool.py:1003,
                             connection (1):                                    ,
                             lichess.org:443                                    ,
[08/21/22 01:23:50] DEBUG    Event: {'type': 'gameFinish',    lichess-bot.py:211,
                             'game': {'fullId':                                 ,
                             'xOUHjoyPQUnw', 'gameId':                          ,
                             'xOUHjoyP', 'fen':                                 ,
                             'rnbqkbnr/pppppppp/8/8/8/2N5/PPP                   ,
                             PPPPP/R1BQKBNR b KQkq - 1 1',                      ,
                             'color': 'black', 'lastMove':                      ,
                             'b1c3', 'source': 'friend',                        ,
                             'variant': {'key': 'standard',                     ,
                             'name': 'Standard'}, 'speed':                      ,
                             'blitz', 'perf': 'blitz',                          ,
                             'rated': True, 'hasMoved':                         ,
                             False, 'opponent': {'id':                          ,
                             'willbochessengine', 'username':                   ,
                             'BOT WillBoChessEngine',                           ,
                             'rating': 2013}, 'isMyTurn':                       ,
                             False, 'secondsLeft': 300,                         ,
                             'compat': {'bot': True, 'board':                   ,
                             True}, 'id': 'xOUHjoyP'}}                          ,
AttackingOrDefending commented 2 years ago

Your bot didn't receive the move that your opponent played. It was probably a connection problem, judging by the Starting new HTTPS connection log.

I also don't know how your bot challenged WillBoChessEngine since you have opponent_allow_tos_violations set to false but your opponent has a tos violation. How often does this problem occur?

MarkZH commented 2 years ago

I also don't know how your bot challenged WillBoChessEngine since you have opponent_allow_tos_violations set to false but your opponent has a tos violation. How often does this problem occur?

As it turns out, that feature doesn't work yet. When getting a player's public data via the /user/{username} API, tosViolations is not included. According to the comment here on discord, such information isn't sent to OAuth token users. I've submitted an issue to ask if this can be changed.

ianagbip1oti commented 2 years ago

Your bot didn't receive the move that your opponent played. It was probably a connection problem, judging by the Starting new HTTPS connection log.

Ok, I'll keep an eye out for if it happens again.

I did have a few in a row where it happened, but didn't have verbose logging enabled

Screen Shot 2022-08-21 at 12 55 22 PM

ianagbip1oti commented 2 years ago

Here is another aborted game, as white this time https://lichess.org/MUaSHQ6C

[08/22/22 00:26:02] INFO     Challenging a random bot         lichess-bot.py:308,
                    DEBUG    Resetting dropped connection: connectionpool.py:273,
                             lichess.org                                        ,
[08/22/22 00:26:05] DEBUG    https://lichess.org:443 "GET  connectionpool.py:456,
                             /api/account HTTP/1.1" 200                         ,
                             None                                               ,
                    INFO     Seeking bullet game with         matchmaking.py:113,
                             opponent rating in [1509, 2309]                    ,
                             ...                                                ,
                    DEBUG    https://lichess.org:443 "GET  connectionpool.py:456,
                             /api/bot/online HTTP/1.1" 200                      ,
                             None                                               ,
[08/22/22 00:26:09] INFO     Will challenge Virutor for a     matchmaking.py:133,
                             standard game.                                     ,
                    DEBUG    https://lichess.org:443 "POST connectionpool.py:456,
                             /api/challenge/Virutor                             ,
                             HTTP/1.1" 200 None                                 ,
                    INFO     Challenge id is MUaSHQ6C.        matchmaking.py:135,
                    DEBUG    Event: {'type': 'challenge',     lichess-bot.py:211,
                             'challenge': {'id': 'MUaSHQ6C',                    ,
                             'url':                                             ,
                             'https://lichess.org/MUaSHQ6C',                    ,
                             'status': 'created',                               ,
                             'challenger': {'id':                               ,
                             'princhess_bot', 'name':                           ,
                             'princhess_bot', 'title': 'BOT',                   ,
                             'rating': 1909, 'online': True},                   ,
                             'destUser': {'id': 'virutor',                      ,
                             'name': 'Virutor', 'title':                        ,
                             'BOT', 'rating': 1677, 'online':                   ,
                             True}, 'variant': {'key':                          ,
                             'standard', 'name': 'Standard',                    ,
                             'short': 'Std'}, 'rated': True,                    ,
                             'speed': 'bullet',                                 ,
                             'timeControl': {'type': 'clock',                   ,
                             'limit': 60, 'increment': 0,                       ,
                             'show': '1+0'}, 'color':                           ,
                             'random', 'finalColor': 'white',                   ,
                             'perf': {'icon': '\ue047',                         ,
                             'name': 'Bullet'}}, 'compat':                      ,
                             {'bot': True, 'board': False}}                     ,
                    DEBUG    Event: {'type': 'gameStart',     lichess-bot.py:211,
                             'game': {'fullId':                                 ,
                             'MUaSHQ6CylBR', 'gameId':                          ,
                             'MUaSHQ6C', 'fen':                                 ,
                             'rnbqkbnr/pppppppp/8/8/8/8/PPPPP                   ,
                             PPP/RNBQKBNR w KQkq - 0 1',                        ,
                             'color': 'white', 'lastMove':                      ,
                             '', 'source': 'friend',                            ,
                             'variant': {'key': 'standard',                     ,
                             'name': 'Standard'}, 'speed':                      ,
                             'bullet', 'perf': 'bullet',                        ,
                             'rated': True, 'hasMoved':                         ,
                             False, 'opponent': {'id':                          ,
                             'virutor', 'username': 'BOT                        ,
                             Virutor', 'rating': 1677},                         ,
                             'isMyTurn': True, 'secondsLeft':                   ,
                             60, 'compat': {'bot': True,                        ,
                             'board': False}, 'id':                             ,
                             'MUaSHQ6C'}}                                       ,
                    INFO     --- Process Used. Total Queued:  lichess-bot.py:182,
                             0. Total Used: 1                                   ,
[08/22/22 00:26:09] DEBUG    Starting new HTTPS           connectionpool.py:1003,
                             connection (1):                                    ,
                             lichess.org:443                                    ,
[08/22/22 00:28:10] DEBUG    Event: {'type': 'gameFinish',    lichess-bot.py:211,
                             'game': {'fullId':                                 ,
                             'MUaSHQ6CylBR', 'gameId':                          ,
                             'MUaSHQ6C', 'fen':                                 ,
                             'rnbqkbnr/pppppppp/8/8/8/8/PPPPP                   ,
                             PPP/RNBQKBNR w KQkq - 0 1',                        ,
                             'color': 'white', 'lastMove':                      ,
                             '', 'source': 'friend',                            ,
                             'variant': {'key': 'standard',                     ,
                             'name': 'Standard'}, 'speed':                      ,
                             'bullet', 'perf': 'bullet',                        ,
                             'rated': True, 'hasMoved':                         ,
                             False, 'opponent': {'id':                          ,
                             'virutor', 'username': 'BOT                        ,
                             Virutor', 'rating': 1677},                         ,
                             'isMyTurn': False,                                 ,
                             'secondsLeft': 60, 'compat':                       ,
                             {'bot': True, 'board': False},                     ,
                             'id': 'MUaSHQ6C'}}                                 ,
[08/22/22 00:28:19] DEBUG    https://lichess.org:443 "GET  connectionpool.py:456,
                             /api/bot/game/stream/MUaSHQ6C                      ,
                             HTTP/1.1" 200 None                                 ,
                    DEBUG    Initial state: {'id':            lichess-bot.py:342,
                             'MUaSHQ6C', 'variant': {'key':                     ,
                             'standard', 'name': 'Standard',                    ,
                             'short': 'Std'}, 'clock':                          ,
                             {'initial': 60000, 'increment':                    ,
                             0}, 'speed': 'bullet', 'perf':                     ,
                             {'name': 'Bullet'}, 'rated':                       ,
                             True, 'createdAt':                                 ,
                             1661127969810, 'white': {'id':                     ,
                             'princhess_bot', 'name':                           ,
                             'princhess_bot', 'title': 'BOT',                   ,
                             'rating': 1909}, 'black': {'id':                   ,
                             'virutor', 'name': 'Virutor',                      ,
                             'title': 'BOT', 'rating': 1677},                   ,
                             'initialFen': 'startpos',                          ,
                             'type': 'gameFull', 'state':                       ,
                             {'type': 'gameState', 'moves':                     ,
                             '', 'wtime': 60000, 'btime':                       ,
                             60000, 'winc': 0, 'binc': 0,                       ,
                             'status': 'aborted'}}                              ,
                    DEBUG    Starting engine:               engine_wrapper.py:34,
                             /engines/princhess                                 ,
                    DEBUG    Using selector: EpollSelector selector_events.py:54,
                    DEBUG    Using PidfdChildWatcher               engine.py:124,
                    DEBUG    <UciProtocol (pid=2043)>: Connection  engine.py:987,
                             made                                               ,
                    DEBUG    <UciProtocol (pid=2043)>: << uci     engine.py:1009,
                    DEBUG    <UciProtocol (pid=2043)>: >> id name engine.py:1035,
                             Princhess 0.0.0-dev                                ,
                    DEBUG    <UciProtocol (pid=2043)>: >> id      engine.py:1035,
                             author Princess Lana                               ,
                    DEBUG    <UciProtocol (pid=2043)>: >> option  engine.py:1035,
                             name Hash type spin min 8 max 65536                ,
                             default 16                                         ,
                    DEBUG    <UciProtocol (pid=2043)>: >> option  engine.py:1035,
                             name Threads type spin min 1 max 255               ,
                             default 1                                          ,
                    DEBUG    <UciProtocol (pid=2043)>: >> option  engine.py:1035,
                             name SyzygyPath type string                        ,
                    DEBUG    <UciProtocol (pid=2043)>: >> option  engine.py:1035,
                             name CPuct type spin min 1 max 65536               ,
                             default 215                                        ,
                    DEBUG    <UciProtocol (pid=2043)>: >> option  engine.py:1035,
                             name CPuctBase type spin min 1 max                 ,
                             65536 default 18368                                ,
                    DEBUG    <UciProtocol (pid=2043)>: >> option  engine.py:1035,
                             name CPuctFactor type spin min 1 max               ,
                             65536 default 282                                  ,
                    DEBUG    <UciProtocol (pid=2043)>: >> uciok   engine.py:1035,
                    DEBUG    <UciProtocol (pid=2043)>: <<         engine.py:1009,
                             setoption name Threads value 2                     ,
                    DEBUG    <UciProtocol (pid=2043)>: <<         engine.py:1009,
                             setoption name Hash value 1024                     ,
                    DEBUG    <UciProtocol (pid=2043)>: <<         engine.py:1009,
                             setoption name SyzygyPath value                    ,
                             /syzygy                                            ,
                    INFO     +++                              lichess-bot.py:350,
                             https://lichess.org/MUaSHQ6C/whi                   ,
                             te Bullet vs BOT Virutor(1677)                     ,
                    DEBUG    Game state: {'type':             lichess-bot.py:392,
                             'gameState', 'moves': '',                          ,
                             'wtime': 60000, 'btime': 60000,                    ,
                             'winc': 0, 'binc': 0, 'status':                    ,
                             'aborted'}                                         ,
                    DEBUG    <UciProtocol (pid=2043)>: <<         engine.py:1009,
                             position startpos                                  ,
                    INFO     Game adjourned.                 lichess-bot.py:1021,
                    INFO     Game aborted.                   lichess-bot.py:1030,
[08/22/22 00:28:43] INFO     Aborting                         lichess-bot.py:468,
                             https://lichess.org/MUaSHQ6C/whi                   ,
                             te by lack of activity                             ,
                    DEBUG    Starting new HTTPS           connectionpool.py:1003,
                             connection (1):                                    ,
                             lichess.org:443                                    ,
[08/22/22 00:28:46] DEBUG    https://lichess.org:443 "POST connectionpool.py:456,
                             /api/bot/game/MUaSHQ6C/abort                       ,
                             HTTP/1.1" 400 46                                   ,
                    DEBUG    Giving up api_post(...) after 1      _common.py:120,
                             tries                                              ,
                             (requests.exceptions.HTTPError: 400                ,
                             Client Error: Bad Request for url:                 ,
                             https://lichess.org/api/bot/game/MUa               ,
                             SHQ6C/abort)                                       ,
                    DEBUG    https://lichess.org:443 "GET  connectionpool.py:456,
                             /api/account/playing                               ,
                             HTTP/1.1" 200 17                                   ,
                    DEBUG    <UciProtocol (pid=2043)>: << stop    engine.py:1009,
                    DEBUG    <UciProtocol (pid=2043)>: << quit    engine.py:1009,
                    DEBUG    <UciProtocol (pid=2043)>: Process    engine.py:1006,
                             exited                                             ,
                    DEBUG    <UciProtocol (pid=2043)>: Connection  engine.py:993,
                             lost (exit code: 0, error: None)                   ,
                    INFO     ---                              lichess-bot.py:496,
                             https://lichess.org/MUaSHQ6C/whi                   ,
                             te Game over                                       ,
[08/22/22 00:28:46] DEBUG    Event: {'type':                  lichess-bot.py:211,
                             'local_game_done'}                                 ,
                    INFO     +++ Process Freed. Total Queued: lichess-bot.py:182,
                             0. Total Used: 0                                   ,
MarkZH commented 2 years ago

Are you still seeing aborted games?

kurt1288 commented 2 years ago

I just updated to the version current as of the date of this comment. Still getting the occasional aborted game. Sometimes it'll run for hours, or even overnight, without a problem and other times it'll run for only a couple games then get stuck.

MarkZH commented 1 year ago

Please try the latest update to see if this problem persists.

MarkZH commented 1 year ago

If this problem still persists, please reopen this issue. Be sure to include the output from verbose logging: python lichess-bot.py -v -l log.txt