"info string" on startup causes assertion

[jdart1]

I am running my engine under lichess-bot with debug tracing enabled. Debug output ("info string") starts being sent after "uci" but before "isready." However, I am getting an assertion from python-chess at that point:

2023-10-02 00:37:03,028 config (config.py:261) DEBUG ====================
2023-10-02 00:37:03,029 __main__ (lichess-bot.py:1001) INFO Checking engine configuration ...
2023-10-02 00:37:03,030 engine_wrapper (engine_wrapper.py:67) DEBUG Starting engine: ['/home/jdart/chess/engines/arasan/arasanx-64-avx2']
2023-10-02 00:37:03,031 asyncio (selector_events.py:54) DEBUG Using selector: EpollSelector
2023-10-02 00:37:03,033 chess.engine (engine.py:124) DEBUG Using PidfdChildWatcher
2023-10-02 00:37:03,035 chess.engine (engine.py:1001) DEBUG <UciProtocol (pid=82785)>: Connection made
2023-10-02 00:37:03,036 chess.engine (engine.py:1023) DEBUG <UciProtocol (pid=82785)>: << uci
2023-10-02 00:37:03,045 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> Arasan v24.0.0-10-g367aa9f Copyright 1994-2023 by Jon Dart. \
All Rights Reserved.
2023-10-02 00:37:03,072 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> in do_all_pending
2023-10-02 00:37:03,074 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> out of do_all_pending, list size=0
2023-10-02 00:37:03,076 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> in do_all_pending
2023-10-02 00:37:03,077 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> pending command(a): uci
2023-10-02 00:37:03,079 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> do_command: uci
2023-10-02 00:37:03,080 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> id name Arasan v24.0.0-10-g367aa9f
2023-10-02 00:37:03,081 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> id author Jon Dart
2023-10-02 00:37:03,083 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name Hash type spin default 64 min 4 max 64000
2023-10-02 00:37:03,085 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name Ponder type check default true
2023-10-02 00:37:03,086 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name Contempt type spin default 0 min -200 max 200
2023-10-02 00:37:03,088 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name Use tablebases type check default true
2023-10-02 00:37:03,089 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name SyzygyTbPath type string default /home/jdart/che\
ss/syzygy:/home/jdart/chess/syzygy-6man/wdl:/home/jdart/chess/syzygy-6man/dtz
2023-10-02 00:37:03,091 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name SyzygyUse50MoveRule type check default true
2023-10-02 00:37:03,093 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name SyzygyProbeDepth type spin default 4 min 0 max 6\
4
2023-10-02 00:37:03,094 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name MultiPV type spin default 1 min 1 max 10
2023-10-02 00:37:03,096 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name OwnBook type check default true
2023-10-02 00:37:03,098 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name Favor frequent book moves type spin default 50 m\
in 0 max 100
2023-10-02 00:37:03,099 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name Favor best book moves type spin default 50 min 0\
 max 100
2023-10-02 00:37:03,101 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name Favor high-weighted book moves type spin default\
 100 min 0 max 100
2023-10-02 00:37:03,103 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name Randomize book moves type spin default 50 min 0 \
max 100
2023-10-02 00:37:03,104 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name Threads type spin default 1 min 1 max 256
2023-10-02 00:37:03,106 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name UCI_LimitStrength type check default false
2023-10-02 00:37:03,107 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name UCI_Elo type spin default 3300 min 1000 max 3300
2023-10-02 00:37:03,109 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name Use NNUE type check default true
2023-10-02 00:37:03,111 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name NNUE file type string default arasan-d9-SFv4-202\
30728.nnue
2023-10-02 00:37:03,112 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> option name Move overhead type spin default 30 min 0 max 100\
0
2023-10-02 00:37:03,114 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> uciok
2023-10-02 00:37:03,115 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> info string out of do_all_pending, list size=0
2023-10-02 00:37:03,117 asyncio (base_events.py:1758) ERROR Exception in callback Protocol._line_received('info string ..., list size=0')
handle: <Handle Protocol._line_received('info string ..., list size=0')>
Traceback (most recent call last):
  File "/usr/lib/python3.10/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/home/jdart/chess/lichess-bot/venv/lib/python3.10/site-packages/chess/engine.py", line 1054, in _line_received
    self.command._line_received(self, line)
  File "/home/jdart/chess/lichess-bot/venv/lib/python3.10/site-packages/chess/engine.py", line 1303, in _line_received
    assert self.state in [CommandState.ACTIVE, CommandState.CANCELLING]
AssertionError
2023-10-02 00:37:03,122 chess.engine (engine.py:1023) DEBUG <UciProtocol (pid=82785)>: << setoption name Threads value 8
2023-10-02 00:37:03,124 chess.engine (engine.py:1023) DEBUG <UciProtocol (pid=82785)>: << setoption name Hash value 32768
2023-10-02 00:37:03,126 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> info string in do_all_pending
2023-10-02 00:37:03,127 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> info string pending command(a): setoption name Threads value\
 8
2023-10-02 00:37:03,129 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> info string do_command: setoption name Threads value 8
2023-10-02 00:37:03,130 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> info string out of do_all_pending, list size=0
2023-10-02 00:37:03,132 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> info string in do_all_pending
2023-10-02 00:37:03,133 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> info string pending command(a): setoption name Hash value 32\
768
2023-10-02 00:37:03,135 chess.engine (engine.py:1049) DEBUG <UciProtocol (pid=82785)>: >> info string do_command: setoption name Hash value 32768
2023-10-02 00:37:03,136 chess.engine (engine.py:1023) DEBUG <UciProtocol (pid=82785)>: << isready

[niklasf]

Thanks for reporting. The spec vaguely implies that info is meant to be sent during search, but I don't think it's clearly stated. So I guess this should be allowed ...

[jdart1]

Other interfaces such as cutechess-cli are ok with this.