search

lichess-bot-devs / lichess-bot

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

Another ChunkedEncodingError #89

Closed gbtami closed 6 years ago

gbtami commented 6 years ago

Strange thing happened last night wile i was sleeping. Here is the full log:

tamas@tami:~/lichess-bot$ python3 main.py -v
.   _/|
.  // o\
.  || ._)  lichess-bot 0.10
.  //__\
.  )___(   Play on Lichess with a bot

DEBUG:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): lichess.org
DEBUG:requests.packages.urllib3.connectionpool:https://lichess.org:443 "GET /account/me HTTP/1.1" 200 None
Welcome PyChessBot!
You're now connected to https://lichess.org/ and awaiting challenges.
DEBUG:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): lichess.org
DEBUG:requests.packages.urllib3.connectionpool:https://lichess.org:443 "GET /api/stream/event HTTP/1.1" 200 None
DEBUG:requests.packages.urllib3.connectionpool:Resetting dropped connection: lichess.org
DEBUG:requests.packages.urllib3.connectionpool:https://lichess.org:443 "POST /challenge/NTvSiJ1L/accept HTTP/1.1" 200 None
    Accept UltraBullet casual challenge from butterfly3(1370)
--- Process Queue. Total Queued: 1. Total Used: 0
--- Process Used. Total Queued: 0. Total Used: 1
DEBUG:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): lichess.org
DEBUG:requests.packages.urllib3.connectionpool:https://lichess.org:443 "GET /bot/game/stream/NTvSiJ1L HTTP/1.1" 400 None
Traceback (most recent call last):
  File "/home/tamas/lichess-bot/logging_pool.py", line 16, in __call__
    result = self.__callable(*args, **kwargs)
  File "main.py", line 103, in play_game
    game = model.Game(json.loads(next(updates).decode('utf-8')), user_profile["username"], li.baseUrl, config.get("abort_time", 20))
  File "/usr/lib/python3.5/json/__init__.py", line 319, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python3.5/json/decoder.py", line 339, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib/python3.5/json/decoder.py", line 357, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

DEBUG:requests.packages.urllib3.connectionpool:Resetting dropped connection: lichess.org
DEBUG:requests.packages.urllib3.connectionpool:https://lichess.org:443 "POST /challenge/aDjeMWPZ/accept HTTP/1.1" 200 None
    Accept UltraBullet casual challenge from butterfly3(1370)
--- Process Queue. Total Queued: 1. Total Used: 1
--- Process Used. Total Queued: 0. Total Used: 2
DEBUG:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): lichess.org
DEBUG:requests.packages.urllib3.connectionpool:https://lichess.org:443 "GET /bot/game/stream/aDjeMWPZ HTTP/1.1" 400 None
Traceback (most recent call last):
  File "/home/tamas/lichess-bot/logging_pool.py", line 16, in __call__
    result = self.__callable(*args, **kwargs)
  File "main.py", line 103, in play_game
    game = model.Game(json.loads(next(updates).decode('utf-8')), user_profile["username"], li.baseUrl, config.get("abort_time", 20))
  File "/usr/lib/python3.5/json/__init__.py", line 319, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python3.5/json/decoder.py", line 339, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib/python3.5/json/decoder.py", line 357, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

DEBUG:requests.packages.urllib3.connectionpool:Resetting dropped connection: lichess.org
DEBUG:requests.packages.urllib3.connectionpool:https://lichess.org:443 "POST /challenge/POO1FC9c/accept HTTP/1.1" 200 None
    Accept UltraBullet rated challenge from butterfly3(1370)
--- Process Queue. Total Queued: 1. Total Used: 2
--- Process Used. Total Queued: 0. Total Used: 3
DEBUG:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): lichess.org
DEBUG:requests.packages.urllib3.connectionpool:https://lichess.org:443 "GET /bot/game/stream/POO1FC9c HTTP/1.1" 400 None
Traceback (most recent call last):
  File "/home/tamas/lichess-bot/logging_pool.py", line 16, in __call__
    result = self.__callable(*args, **kwargs)
  File "main.py", line 103, in play_game
    game = model.Game(json.loads(next(updates).decode('utf-8')), user_profile["username"], li.baseUrl, config.get("abort_time", 20))
  File "/usr/lib/python3.5/json/__init__.py", line 319, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python3.5/json/decoder.py", line 339, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib/python3.5/json/decoder.py", line 357, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

DEBUG:requests.packages.urllib3.connectionpool:Resetting dropped connection: lichess.org
DEBUG:requests.packages.urllib3.connectionpool:https://lichess.org:443 "POST /challenge/ews3gxKx/accept HTTP/1.1" 200 None
    Accept UltraBullet rated challenge from butterfly3(1370)
--- Process Queue. Total Queued: 1. Total Used: 3
--- Process Used. Total Queued: 0. Total Used: 4
DEBUG:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): lichess.org
DEBUG:requests.packages.urllib3.connectionpool:https://lichess.org:443 "GET /bot/game/stream/ews3gxKx HTTP/1.1" 400 None
Traceback (most recent call last):
  File "/home/tamas/lichess-bot/logging_pool.py", line 16, in __call__
    result = self.__callable(*args, **kwargs)
  File "main.py", line 103, in play_game
    game = model.Game(json.loads(next(updates).decode('utf-8')), user_profile["username"], li.baseUrl, config.get("abort_time", 20))
  File "/usr/lib/python3.5/json/__init__.py", line 319, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python3.5/json/decoder.py", line 339, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib/python3.5/json/decoder.py", line 357, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

Process Process-2:
Traceback (most recent call last):
  File "/home/tamas/.local/lib/python3.5/site-packages/requests/packages/urllib3/response.py", line 535, in _update_chunk_length
    self.chunk_left = int(line, 16)
ValueError: invalid literal for int() with base 16: b''

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/tamas/.local/lib/python3.5/site-packages/requests/packages/urllib3/response.py", line 298, in _error_catcher
    yield
  File "/home/tamas/.local/lib/python3.5/site-packages/requests/packages/urllib3/response.py", line 590, in read_chunked
    self._update_chunk_length()
  File "/home/tamas/.local/lib/python3.5/site-packages/requests/packages/urllib3/response.py", line 539, in _update_chunk_length
    raise httplib.IncompleteRead(line)
http.client.IncompleteRead: IncompleteRead(0 bytes read)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/tamas/.local/lib/python3.5/site-packages/requests/models.py", line 703, in generate
    for chunk in self.raw.stream(chunk_size, decode_content=True):
  File "/home/tamas/.local/lib/python3.5/site-packages/requests/packages/urllib3/response.py", line 428, in stream
    for line in self.read_chunked(amt, decode_content=decode_content):
  File "/home/tamas/.local/lib/python3.5/site-packages/requests/packages/urllib3/response.py", line 618, in read_chunked
    self._original_response.close()
  File "/usr/lib/python3.5/contextlib.py", line 77, in __exit__
    self.gen.throw(type, value, traceback)
  File "/home/tamas/.local/lib/python3.5/site-packages/requests/packages/urllib3/response.py", line 316, in _error_catcher
    raise ProtocolError('Connection broken: %r' % e, e)
requests.packages.urllib3.exceptions.ProtocolError: ('Connection broken: IncompleteRead(0 bytes read)', IncompleteRead(0 bytes read))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.5/multiprocessing/process.py", line 249, in _bootstrap
    self.run()
  File "/usr/lib/python3.5/multiprocessing/process.py", line 93, in run
    self._target(*self._args, **self._kwargs)
  File "main.py", line 35, in watch_control_stream
    for evnt in li.get_event_stream().iter_lines():
  File "/home/tamas/.local/lib/python3.5/site-packages/requests/models.py", line 747, in iter_lines
    for chunk in self.iter_content(chunk_size=chunk_size, decode_unicode=decode_unicode):
  File "/home/tamas/.local/lib/python3.5/site-packages/requests/models.py", line 706, in generate
    raise ChunkedEncodingError(e)
requests.exceptions.ChunkedEncodingError: ('Connection broken: IncompleteRead(0 bytes read)', IncompleteRead(0 bytes read))

Then I stopped, updated, and restarted my lichess-bot. I got this:

tamas@tami:~/lichess-bot$ python3 lichess-bot.py -v
.   _/|
.  // o\
.  || ._)  lichess-bot 0.11
.  //__\
.  )___(   Play on Lichess with a bot

DEBUG:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): lichess.org
DEBUG:requests.packages.urllib3.connectionpool:https://lichess.org:443 "GET /api/account HTTP/1.1" 200 None
Welcome PyChessBot!
You're now connected to https://lichess.org/ and awaiting challenges.
DEBUG:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): lichess.org
DEBUG:requests.packages.urllib3.connectionpool:https://lichess.org:443 "GET /api/stream/event HTTP/1.1" 200 None
Something went wrong. Game is starting and we don't have a queued process
--- Process Used. Total Queued: 0. Total Used: 1
DEBUG:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): lichess.org
DEBUG:requests.packages.urllib3.connectionpool:https://lichess.org:443 "GET /api/bot/game/stream/POO1FC9c HTTP/1.1" 200 None
DEBUG:chess.engine:<PopenProcess at 0x7ff0b0ab8978 (pid=10711)> << xboard
DEBUG:chess.engine:<PopenProcess at 0x7ff0b0ab8978 (pid=10711)> << protover 2
DEBUG:chess.engine:<PopenProcess at 0x7ff0b0ab8978 (pid=10711)> << post
DEBUG:chess.engine:<PopenProcess at 0x7ff0b0ab8978 (pid=10711)> << easy
DEBUG:chess.engine:<PopenProcess at 0x7ff0b0ab8978 (pid=10711)> << ping 123
DEBUG:chess.engine:<PopenProcess at 0x7ff0b0ab8978 (pid=10711)> >> # PyChess 0.99.1 [pypy3 3.5.3]
DEBUG:chess.engine:<PopenProcess at 0x7ff0b0ab8978 (pid=10711)> >> feature ping=1 setboard=1 playother=1 san=1 usermove=1 time=1 draw=1 sigint=0 sigterm=0 reuse=1 analyze=1 myname="PyChess 0.99.1" variants="normal,wildcastle,nocastle,fischerandom,crazyhouse,losers,suicide,giveaway,horde,atomic,racingkings,kingofthehill,3check,asean,cambodian,makruk,sittuyin" colors=0 ics=0 name=0 pause=0 nps=0 debug=1 memory=0 smp=0 egt="gaviota" option="skipPruneChance -slider 0 0 100"
DEBUG:chess.engine:<PopenProcess at 0x7ff0b0ab8978 (pid=10711)> >> feature done=1
DEBUG:chess.engine:<PopenProcess at 0x7ff0b0ab8978 (pid=10711)> >> pong 123
DEBUG:chess.engine:<PopenProcess at 0x7ff0b0ab8978 (pid=10711)> << egtpath gaviota ../Gaviota/Gaviota
DEBUG:chess.engine:<PopenProcess at 0x7ff0b0ab8978 (pid=10711)> << force
DEBUG:chess.engine:<PopenProcess at 0x7ff0b0ab8978 (pid=10711)> << setboard rnbqkbnr/pppppppp/8/8/3P4/8/PPP1PPPP/RNBQKBNR b KQkq - 0 1
+++ https://lichess.org/POO1FC9c/black UltraBullet vs butterfly3(1370)
DEBUG:chess.engine:<PopenProcess at 0x7ff0b0ab8978 (pid=10711)> << level 0 0:15 0
DEBUG:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): lichess.org
DEBUG:requests.packages.urllib3.connectionpool:https://lichess.org:443 "POST /api/bot/game/POO1FC9c/move/d7d5 HTTP/1.1" 200 None
--- https://lichess.org/POO1FC9c/black Game over
DEBUG:chess.engine:<PopenProcess at 0x7ff0b0ab8978 (pid=10711)> << quit
+++ Process Free. Total Queued: 0. Total Used: 0

Seems butterfly3 challenged 4 games 2 hours ago. 3 was aborted, but in game https://lichess.org/POO1FC9ctqYn 1. d4 d5 happened. It was not aborted contrary after I restarted pychess-bot this morning butterfly3 lost it on time. My config.yml

token: "xxxxxxxxxxxxxxxx"    # lichess OAuth2 Token
url: "https://lichess.org/"  # lichess base URL

engine:                      # engine settings
  dir: "./engines/"          # dir containing engines, relative to this project
  name: "pychess-engine"     # binary name of the engine to use
  protocol: "xboard"         # "uci" or "xboard"
#  weights: "latest.txt"     # only if the engine is lczero
#  threads: 1                # only if the engine is lczero
  polyglot: true            # activate polyglot book
  polyglot_book: "dc-3200.bin"  # book file name, must be in engine.dir
  polyglot_max_depth: 8      # half move max depth
  polyglot_min_weight: 1     # best move weight
  polyglot_random: true      # select move randomly otherwise select by min weight

ucioptions:                  # arbitrary UCI options passed to the engine
  Move Overhead: 100         # increase if your bot flags games too often
#  Threads: 4
#  Hash: "4096"
#  Book File: "engines/book.bin"

xboardoptions:
#  memory: "4096"
#  cores: "4"
  egtpath:                   # type and dir of end game tablebases
    gaviota: "../Gaviota/Gaviota"
#    nalimov: "Nalimov Path"
#    scorpio: "Scorpio Path"
#    syzygy: "Syzygy Path"

max_concurrent_games: 4      # number of games to play simultaneously
sort_challenges_by: "rating" # possible values: "rating", "date"
abort_time: 20
accept_bot_challenges: false

supported_variants:          # chess variants to accept (http://lichess.org/variant)
  - standard
  - fromPosition
  - antichess
  - atomic
  - chess960
  - crazyhouse
  - horde
  - kingOfTheHill
  - racingKings
  - threeCheck

supported_tc:                # time controls to accept
  - ultraBullet
  - bullet
  - blitz
  - rapid
#  - classical
#  - correspondence

supported_modes:             # game modes to accept
  - casual                   # unrated games
  - rated                    # rated games - must comment if the engine doesn't try to win

print_engine_stats: true     # print engine stats on each move
ShailChoksi commented 6 years ago

Lost on time could be due to the rate limiting.

gbtami commented 6 years ago

Yes, But the problem here is the not handled exception.

ShailChoksi commented 6 years ago

@gbtami is this still happening? Also are you running a modified version of lichess-bot? Have you found a way to reproduce this?

gbtami commented 6 years ago

No, i can't reproduce this. I think https://github.com/careless25/lichess-bot/commit/6c03b0dc6f3c527ee14c8928449862dc23089dde fixed it.