search

timraay / HLLLogUtilities

A Discord bot that makes it easy to capture and export logs from your HLL servers
MIT License
9 stars 6 forks source link

pop from empty list #10

Closed FlorianSW closed 1 year ago

FlorianSW commented 1 year ago

Today we had a Seasonal match again and used the HLU to capture logs. However, sadly, the tool errored out from the beginning with the following error messages:

[2022-12-04 19:03:28,274][INFO][rcon.wrapper:37] Starting RCON...
[2022-12-04 19:03:28,278][INFO][protocol.connection_made:21] Connection made! Transport: <_SelectorSocketTransport fd=12 read=idle write=<idle, bufsize=0>>
[2022-12-04 19:03:28,879][INFO][rcon.start:126] Started worker Worker #1
[2022-12-04 19:03:28,883][INFO][protocol.connection_made:21] Connection made! Transport: <_SelectorSocketTransport fd=13 read=idle write=<idle, bufsize=0>>
[2022-12-04 19:03:29,427][INFO][rcon.start:126] Started worker Worker #2
[2022-12-04 19:03:29,431][INFO][protocol.connection_made:21] Connection made! Transport: <_SelectorSocketTransport fd=14 read=idle write=<idle, bufsize=0>>
[2022-12-04 19:03:29,976][INFO][rcon.start:126] Started worker Worker #3
[2022-12-04 19:03:29,981][INFO][protocol.connection_made:21] Connection made! Transport: <_SelectorSocketTransport fd=15 read=idle write=<idle, bufsize=0>>
[2022-12-04 19:03:30,476][INFO][rcon.start:126] Started worker Worker #4
[2022-12-04 19:03:30,476][INFO][rcon.wrapper:39] Started RCON!
[2022-12-04 19:03:30,527][ERROR][rcon.wrapper:81] Missed 1 consecutive updates for <lib.rcon.HLLRcon object at 0x7f05bd951d00>, 19 attempts left
Traceback (most recent call last):
  File "/code/lib/rcon.py", line 78, in wrapper
    res = await asyncio.wait_for(func(self, *args, **kwargs), timeout=10)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 494, in wait_for
    return fut.result()
  File "/code/lib/rcon.py", line 155, in update
    await self._fetch_server_info()
  File "/code/lib/rcon.py", line 161, in _fetch_server_info
    res = await asyncio.gather(
  File "/code/lib/rcon.py", line 275, in __fetch_current_server_info
    map, playerids = await asyncio.gather(
  File "/code/lib/rcon.py", line 254, in exec_command
    res = await fut
  File "/code/lib/rcon.py", line 747, in _worker
    res = await self.protocol.execute(cmd, **kwargs)
  File "/code/lib/protocol.py", line 123, in execute
    raise HLLUnpackError("Expected array size %s but got %s", arr_size, len(res))
lib.exceptions.HLLUnpackError: ('Expected array size %s but got %s', 100, 41)
[2022-12-04 19:03:30,541][ERROR][base_events.default_exception_handler:1707] Fatal error: protocol.data_received() call failed.
protocol: <lib.protocol.HLLRconProtocol object at 0x7f05bda837c0>
transport: <_SelectorSocketTransport fd=14 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 862, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/code/lib/protocol.py", line 34, in data_received
    waiter = self._waiters.pop(0)
IndexError: pop from empty list
[2022-12-04 19:03:30,543][CRITICAL][protocol.connection_lost:41] Connection lost: pop from empty list
[2022-12-04 19:03:30,543][ERROR][base_events.default_exception_handler:1707] Exception in callback _SelectorSocketTransport._call_connection_lost(IndexError('p...m empty list'))
handle: <Handle _SelectorSocketTransport._call_connection_lost(IndexError('p...m empty list'))>
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/asyncio/events.py", line 81, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 970, in _call_connection_lost
    super()._call_connection_lost(exc)
  File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 728, in _call_connection_lost
    self._protocol.connection_lost(exc)
  File "/code/lib/protocol.py", line 44, in connection_lost
    raise HLLConnectionLostError(exc)
lib.exceptions.HLLConnectionLostError: pop from empty list
[2022-12-04 19:03:35,478][INFO][rcon.wrapper:73] Trying to reconnect <lib.rcon.HLLRcon object at 0x7f05bd951d00>
[2022-12-04 19:03:35,479][INFO][rcon.wrapper:37] Starting RCON...
[2022-12-04 19:03:35,480][WARNING][rcon.start:118] Stopped leftover worker <lib.rcon.HLLRconWorker object at 0x7f05be3b4490>, possibly the source was not properly stopped.
[2022-12-04 19:03:35,480][WARNING][rcon.start:118] Stopped leftover worker <lib.rcon.HLLRconWorker object at 0x7f05bda83d00>, possibly the source was not properly stopped.
[2022-12-04 19:03:35,480][WARNING][rcon.start:118] Stopped leftover worker <lib.rcon.HLLRconWorker object at 0x7f05bda83ca0>, possibly the source was not properly stopped.
[2022-12-04 19:03:35,480][WARNING][rcon.start:118] Stopped leftover worker <lib.rcon.HLLRconWorker object at 0x7f05bd951fd0>, possibly the source was not properly stopped.
[2022-12-04 19:03:35,480][CRITICAL][protocol.connection_lost:41] Connection lost: None
[2022-12-04 19:03:35,480][CRITICAL][protocol.connection_lost:41] Connection lost: None
[2022-12-04 19:03:35,481][CRITICAL][protocol.connection_lost:41] Connection lost: None
[2022-12-04 19:03:35,485][INFO][protocol.connection_made:21] Connection made! Transport: <_SelectorSocketTransport fd=12 read=idle write=<idle, bufsize=0>>
[2022-12-04 19:03:35,723][INFO][rcon.start:126] Started worker Worker #1
[2022-12-04 19:03:35,728][INFO][protocol.connection_made:21] Connection made! Transport: <_SelectorSocketTransport fd=13 read=idle write=<idle, bufsize=0>>
[2022-12-04 19:03:36,273][INFO][rcon.start:126] Started worker Worker #2
[2022-12-04 19:03:36,277][INFO][protocol.connection_made:21] Connection made! Transport: <_SelectorSocketTransport fd=14 read=idle write=<idle, bufsize=0>>
[2022-12-04 19:03:36,823][INFO][rcon.start:126] Started worker Worker #3
[2022-12-04 19:03:36,828][INFO][protocol.connection_made:21] Connection made! Transport: <_SelectorSocketTransport fd=15 read=idle write=<idle, bufsize=0>>
[2022-12-04 19:03:37,374][INFO][rcon.start:126] Started worker Worker #4
[2022-12-04 19:03:37,374][INFO][rcon.wrapper:39] Started RCON!
[2022-12-04 19:03:37,374][INFO][rcon.reconnect:67] Reconnected <lib.rcon.HLLRcon object at 0x7f05bd951d00>!
[2022-12-04 19:03:37,424][ERROR][rcon.wrapper:81] Missed 2 consecutive updates for <lib.rcon.HLLRcon object at 0x7f05bd951d00>, 18 attempts left
Traceback (most recent call last):
  File "/code/lib/rcon.py", line 78, in wrapper
    res = await asyncio.wait_for(func(self, *args, **kwargs), timeout=10)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 494, in wait_for
    return fut.result()
  File "/code/lib/rcon.py", line 155, in update
    await self._fetch_server_info()
  File "/code/lib/rcon.py", line 161, in _fetch_server_info
    res = await asyncio.gather(
  File "/code/lib/rcon.py", line 275, in __fetch_current_server_info
    map, playerids = await asyncio.gather(
  File "/code/lib/rcon.py", line 254, in exec_command
    res = await fut
  File "/code/lib/rcon.py", line 747, in _worker
    res = await self.protocol.execute(cmd, **kwargs)
  File "/code/lib/protocol.py", line 123, in execute
    raise HLLUnpackError("Expected array size %s but got %s", arr_size, len(res))
lib.exceptions.HLLUnpackError: ('Expected array size %s but got %s', 100, 41)
Loaded all cogs
Loading release: v1.2.0
Synced app commands

Launched HLL Recorder on 2022-12-04 14:57:58.108822
ID: 1044360197294018626
NO WAITER: b'\x8bl\xf2#\xb4$\x83A\xf9$\xebP\xd46\x83\xd6\x0b*\xa5v\xd5=\xa55\x87x\xfc#\x88n\xfa$\x84`\xf9 \x8ba\xf8"\x8aa\xf9\x1c\xc1\x10\x9fQ\xff$\xeb;\xd67\x995\x87x\xfc#\x88n\xfa$\x84o\xf2-\x8ch\xf8\'\x8el\xf9\x1c\xc1\x10\x9fQ\xc1x\x8cF\xfc\x13\xf3\'\x8fx\xf15\x8an\xfe#\x8ci\xf2,\x8cl\xfe#\x8f`\xf8"\x8bQ\xb7]\xe9\x1c\xb75\xf5-\xa6x\xd84\xeb/\x9do\xfd \x8bi\xfa,\x85i\xfe!\x8dm\xfa"\x8ah\xc2N\xfa\n\xe6&\xe0x\xb75\xee(\xaeo\xd49\xa7s\xd2*\xa85\x87x\xfc#\x88n\xfa$\x84`\xfa#\x8fl\xfe,\x89j\xfc\x1c\x84i\xe5E\xc7\x1f\xb75\xee=\xa9z\x9db\xeb"\x8bm\xfd$\x8ca\xf3\'\x8ak\xfa\'\x8dm\xfa%\xb4$\x83A\xf9\x1a\xb75\xf64\xa2{\xda=\xeb/\x9do\xfd \x8bi\xfa,\x85h\xf9&\x85o\xf9&\x88`\xc2N\xfc\x0e\x88H\x9d\n\xb15\x87x\xfc#\x88n\xfa$\x84o\xf2"\x84n\xf9!\x84k\xfd\x1c\xe6i\xf9#\xe0\x1d\xafy\xd8\x1e\xa4y\x9db\xeb"\x8bm\xfd$\x8ca\xf3%\x8dh\xf9 \x8dh\xf8!\xb4$\x83A\xf9$\xeb]\xc4<\xb9t\xd3,\xae{\xea1\xa7y\xd4x\xf15\x8an\xfe#\x8ci\xf2"\x84o\xfd%\x8bh\xfc \x88Q\xb7]\xe9\x1c\xb75\xfc4\xaem\xf91\xaef\xf99\xb85\x87x\xfc#\x88n\xfa$\x84`\xf3"\x8fk\xf9&\x88h\xfe\x1c\xe6i\xf9#\xe0x\x8ao\xd8*\xa0p\xc4x;\x8a/\xd8\xeb/\x9do\xfd \x8bi\xfa,\x8aa\xf2#\x8eh\xff,\x8fn\xc2N\xfc\n\x88H\x9d\x1b\xa4{\xd6=\xb95\x87x\xfc#\x88n\xfa$\x84`\xf9-\x8ei\xfa!\x8f`\xf2\x1c\xe6i\xf9#\xe0\x1b\xa3t\xcf,\xb9p\xc8 \xeb/\x9do\xfd \x8bi\xfa,\x85i\xfe#\x8fn\xf8"\x8fm\xc2N\xfc\n\x88H\x9d\x1b\xa3t\xd0!\xe6S\xcfx\xf15\x8an\xfe#\x8ci\xf2-\x8da\xf8"\x84h\xf8 \x8eQ\x90T\xef\x1b\x965\xf37\xb9x\xdc6\xaf|\xd8i\xf2!\x89x\xf15\x8an\xfe#\x8ci\xf2-\x8da\xfd \x8fm\xfb \x8dQ\x90T\xef\x1b\x965\xf07\xbeo\xd81\xa7y\xd8x)\x8d8\xbbH\x91\x9db\xeb"\x8bm\xfd$\x8ca\xf3%\x8co\xf8#\x8el\xfd%\xb4\x03\x8aG\xfe\x05\xebS\xcf9\xb2t\xd1x)\x8d8\xbbH\x91\x9db\xeb"\x8bm\xfd$\x8ca\xf3%\x84k\xf2#\x8en\xfb \xb4\x03\x8aG\xfe\x05\xeb[\xfc\x13\x8e[\x9db\xeb"\x8bm\xfd$\x8ca\xf3$\x8ck\xfb$\x8fi\xfe!\xb4\x03\xfa\'\x8b\x05\x81|\xd0u\x8eq\xca9\xb9q\x9db\xeb"\x8bm\xfd$\x8ca\xf3$\x8cm\xff \x8di\xf9 \xb4\x03\x8aG\xfe\x05\xebX\xdc \xa9|\xd0x\xf15\x8an\xfe#\x8ci\xf2"\x84a\xfb,\x8bh\xfd%\x8cQ\x90T\xef\x1b\x965\xf09\x08\xbe\xd1+\xbfg\xd25\xeb/\x9do\xfd \x8bi\xfa,\x85h\xfd&\x8bm\xf9-\x8aj\xc2N\xfc\n\x88H\x9d\x0b\xa3|\xdb,\xb25\x87x\xfc#\x88n\xfa$\x84`\xfb&\x84i\xfb#\x89o\xff\x1c\xe6\x19\x99V\xe0x\x99T\xed\x19\x9f@\xeex\xf15\x8an\xfe#\x8ci\xf2-\x8dh\xfd-\x8aa\xfb%\x8eQ\x90T\xef\x1b\x965\xf9r\xf7+\x81x\xf15\x8an\xfe#\x8ci\xf2"\x84n\xfb&\x8aj\xf8!\x8aQ\x90T\xef\x1b\x965\xfa\n\x82X\x9db\xeb"\x8bm\xfd$\x8ca\xfc,\x85a\xf9 \x88h\xf3"\xb4\x03\x8aG\xfe\x05\xebV\xd84\xae{\xd4\x13\xeb/\x9do\xfd \x8bi\xfa,\x8aa\xfd!\x8dj\xf9%\x8ci\xc2N\xfc\n\x88H\x9d\x0b\xa8t\xd17\xbe5\x87x\xfc#\x88n\xfa$\x84`\xfb-\x85a\xff-\x89n\xfe\x1c\xe6\x19\x99V\xe0x\x86t\xe9=\xa15_\xc0N\xf6>\xdc\xeb/\x9do\xfd \x8bi\xfa,\x8aa\xf3&\x8c`\xfb&\x8co\xc2N\x8cj\xfdH\x9d\x08\xa4`\xd43\xeb/\x9do\xfd \x8bi\xfa,\x8aa\xfd"\x8ca\xff,\x8fa\xc2N\xfc\n\x88H\x9d\x13\xb9z\xd5\x15\xeb/\x9do\xfd \x8bi\xfa,\x85l\xfa$\x8bh\xfc!\x84o\xc2N\xfc\n\x88H\x9d\x0b\xa3t\xcf3\xeb/\x9do\xfd \x8bi\xfa,\x84j\xfb-\x8co\xff!\x85`\xc2N\xfc\n\x88H\x9d\x1d\xb3E\xd86\xeb/\x9do\xfd \x8bi\xfa,\x85h\xff"\x85j\xf3-\x8fa\xc2N\xfc\n\x88H\x9d\x1e\xbe{\xd6\x7f\xb85\x87x\xfc#\x88n\xfa$\x84`\xfb$\x8dj\xf9 \x88l\xfc\x1c\xe6i\xf9#\xe0\x1e\xaaa\xdc\x1f\xa7|\xc7x\xf15\x8an\xfe#\x8ci\xf2-\x8do\xfc-\x88l\xf2%\x88Q\x90$\x8fn\x965\xfc:\xb9t\xd59\xa65\x87x\xfc#\x88n\xfa$\x84o\xf2,\x8bo\xfe!\x89`\xfd\x1c\xe6\x19\x99V\xe0x\x82o\xd4\x08\xaet\xce!\xeb/\x9do\xfd \x8bi\xfa,\x85h\xfa%\x85l\xfb-\x88i\xc2N\x8cj\xfdH\x9d\x17\xa9Y\xd4\x1a\xeb/\x9do\xfd \x8bi\xfa,\x8aa\xfc\'\x8dk\xf3%\x84o\xc2N\xfc\n\x88H\x9d\x0b\xbb|\xd6=\xbe|\xd14\xaa`\xd0=\xeb/\x9do\xfd \x8bi\xfa,\x85h\xfa\'\x8bi\xf2#\x88`\xc2N\xfc\n\x88H\xe2\n\x8e5\x87x\xfc#\x88n\xfa$\x84`\xf2#\x84k\xf2,\x8fi\xfc\x1c\xe6\x19\x99V\xe0x\x99t\xcd0\xa2f\xc9h\xa7p\x9db\xeb"\x8bm\xfd$\x8ca\xf3"\x84m\xfc-\x89o\xfe&\xb4\x03\x8aG\xfe\x05\xebC\xdc4\xaa~\x9db\xeb"\x8bm\xfd$\x8ca\xf3%\x8c`\xf3!\x8bj\xfb!\xb4\x03\x8aG\xfe\x05\xebQ\xd8+\xb8l\x9db\xeb"\x8bm\xfd$\x8ca\xf3%\x8do\xf3$\x8co\xfa#\xb4\x03\x8aG\xfe\x05\xebA\xc7=\xae{\xc9;\xa35\x87x\xfc#\x88n\xfa$\x84o\xf2"\x84o\xf3\'\x8fk\xf8\x1c\xe6\x19\x99V\xe0x\x8ag\xd2:\xaew\xfc+\xae5\x87x\xfc#\x88n\xfa$\x84o\xf2"\x85o\xfc \x8fn\xf9\x1c\xe6\x19\x99V\xe0x\x8ft\xcf3\xbb|\xc9x;\x8a,\xe3\xeb/\x9do\xfd \x8bi\xfa,\x85h\xf3#\x8ah\xf2!\x8el\xc2N\xfc\n\x88H\x9d\n\xa4|\xe2\x19\xb9t\xde0\xa5|\xd9=\xeb/\x9do\xfd \x8bi\xfa,\x85h\xf9\'\x85`\xfa$\x85n\xc2N\x8cj\xfdH\x9d\x08\xa4f\x8dk\xf3s\x9db\xeb"\x8bm\xfd$\x8ca\xf3%\x8cm\xfd,\x8ak\xfe$\xb4\x03\xfa\'\x8b\x05\x98p\xd0=\xb2t\x9db\xeb"\x8bm\xfd$\x8ca\xfc,\x85h\xfd#\x8eo\xf2#\xb4\x03\x8aG\xfe\x05\xeb~\xd43\xa25\x87x\xfc#\x88n\xfa$\x84`\xf8&\x84a\xfe$\x8fj\xf8\x1c\xe6\x19\x99V\xe0x\x98e\xdc*\xbft\xd3i\xfa"\x9db\xeb"\x8bm\xfd$\x8ca\xf3%\x89j\xfd \x8bj\xf9&\xb4\x03\x8aG\xfe\x05\xebT\xd19\xafg\xd44\xeb/\x9do\xfd \x8bi\xfa,\x8aa\xfc$\x85j\xf9 \x84`\xc2N\xfc\n\x88H\x9d\x1c\x92Q\xee\x17\xeb\xf7%\xdd(\x969x\xf15\x8an\xfe#\x8ci\xf2-\x8da\xfa&\x8fo\xfd,\x8fQ\x90T\xef\x1b\x965\xf69\xa45\x87x\xfc#\x88n\xfa$\x84o\xf2"\x84`\xf8-\x8do\xfa\x1c\xe6\x19\x99V\xe0x\xbf{\x8b\x10\x84A\x9db\xeb"\x8bm\xfd$\x8ca\xf3%\x8c`\xfc!\x8ah\xf2"\xb4\x03\x8aG\xfe\x05\xeb^\xd49\xb95\x87x\xfc#\x88n\xfa$\x84o\xf2-\x88i\xf2,\x88n\xf9\x1c\xe6\x19\x99V\xe0x\x9bg\xdc<\xaal\x9db\xeb"\x8bm\xfd$\x8ca\xf3%\x8an\xfe$\x89m\xf3$\xb4\x03\x8aG\xfe\x05\xebY\xdc;\xa3z\xce=\xeb/\x9do\xfd \x8bi\xfa,\x85k\xf2&\x88`\xfb,\x89h\xc2N\xfc\n\x88H\x9d:\xae{\x8ei\xf3$\x9db\xeb"\x8bm\xfd$\x8ca\xf3%\x88m\xfb#\x8bh\xf3,\xb4'
[2022-12-04 19:03:37,426][ERROR][base_events.default_exception_handler:1707] Fatal error: protocol.data_received() call failed.
protocol: <lib.protocol.HLLRconProtocol object at 0x7f05bd9514f0>
transport: <_SelectorSocketTransport fd=14 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 862, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/code/lib/protocol.py", line 34, in data_received
    waiter = self._waiters.pop(0)
IndexError: pop from empty list
[2022-12-04 19:03:37,427][CRITICAL][protocol.connection_lost:41] Connection lost: pop from empty list

The settings were the same than the last time we captured logs, however, this time with the latest release from some days ago.

timraay commented 1 year ago

Just saw this, it is the same issue I observed happening in someone else's session. It's being tracked in #11