[Bug] ASIC Timelord Log Spam and Output Error

What happened?

While testing the ASIC timelord I ran across a couple of bugs and warning logs worth discussing (more details about each are below):

Log spam and associated socket error (chia logs)
too much work for VDF aux thread warning (timelord output) - note this is not a bug but I am curious to have more information about the warning

Log spam when ASIC is offline but chia timelord service is running. To reproduce, run a node and timelord-only then launch the asic chi-hw-vdf. After some time stop the chia-hw-vdf and look at the chia logs for the spam. The chia timelord needs to be restarted to stop the spamming (first glance it seems this might be related to the type being used for the peak in the rpc call here and the log line is here):


2024-04-11T16:52:55.512 timelord chia.timelord.timelord_state: INFO     Updated timelord peak to b'.\x1b\xa2;&\xa6\xbcr!u\xd5\xb1\xfa\xab\x14i\xde\x95!@B\xe6jGo\x82\x1e,)l[\xf3', total iters: 8203443199225
2024-04-11T16:52:55.513 timelord chia.timelord.timelord   : INFO     Total unfinished blocks: 4108. Total infused blocks: 4101. Infusion rate: 99.83%.
2024-04-11T16:52:55.513 timelord asyncio                  : WARNING  socket.send() raised exception.
2024-04-11T16:52:55.513 timelord chia.timelord.timelord   : ERROR    Exception in stop chain: <class 'BrokenPipeError'> [Errno 32] Broken pipe
2024-04-11T16:52:55.513 timelord asyncio                  : WARNING  socket.send() raised exception.
2024-04-11T16:52:55.513 timelord chia.timelord.timelord   : ERROR    Exception in stop chain: <class 'BrokenPipeError'> [Errno 32] Broken pipe
2024-04-11T16:52:55.514 timelord asyncio                  : WARNING  socket.send() raised exception.
2024-04-11T16:52:55.561 timelord chia.timelord.timelord   : ERROR    Error while handling message: Traceback (most recent call last):
File "chia/timelord/timelord.py", line 893, in _manage_chains
File "chia/timelord/timelord.py", line 440, in _submit_iterations
File "asyncio/streams.py", line 359, in drain
File "chia/timelord/timelord.py", line 221, in _stop_chain
File "asyncio/streams.py", line 359, in drain
File "chia/timelord/timelord.py", line 893, in _manage_chains
File "chia/timelord/timelord.py", line 440, in _submit_iterations
File "asyncio/streams.py", line 359, in drain
File "chia/timelord/timelord.py", line 893, in _manage_chains
File "chia/timelord/timelord.py", line 440, in _submit_iterations
File "asyncio/streams.py", line 359, in drain


Note - the above socket error corresponds to the `Bad data size after stop: -1` error seen in the timelord output:

2024-04-12T10:16:52.427 VDF 0: Proof done for iters=28221095, length=925095 in 5.424s 2024-04-12T10:16:52.898 VDF 2: Starting proof thread 1 for iters=34224000, length=1564000 [checkpoint] 2024-04-12T10:16:52.900 VDF 1: Starting proof thread 5 for iters=34224000, length=1564000 [checkpoint] 2024-04-12T10:16:53.172 VDF 0: Stop requested 2024-04-12T10:16:53.173 2024-04-12T10:16:53.173 VDF 0: 34494437 HW iters done in 33s, HW speed: 1016771 ips 2024-04-12T10:16:53.173 VDF 0: 3938133 SW iters done in 67s, SW speed: 58427 ips 2024-04-12T10:16:53.173 VDF 0: Avg iters per intermediate: 490 2024-04-12T10:16:53.173 VDF 0: Bad VDF values observed: 1 2024-04-12T10:16:53.173 2024-04-12T10:16:53.178 VDF 0: Proof stopped 2024-04-12T10:16:53.182 VDF 0: Proof stopped 2024-04-12T10:16:53.182 VDF 0: Proof stopped 2024-04-12T10:16:53.184 VDF 0: Proof stopped 2024-04-12T10:16:53.196 VDF 0: Stopped at iters=34494437 2024-04-12T10:16:53.196 Bad data size after stop: -1 2024-04-12T10:16:53.196 VDF 0: Connection closed 2024-04-12T10:16:53.196 VDF 1: Stop requested 2024-04-12T10:16:53.196 2024-04-12T10:16:53.196 VDF 1: 34498575 HW iters done in 33s, HW speed: 1016211 ips 2024-04-12T10:16:53.196 VDF 1: 4136252 SW iters done in 70s, SW speed: 58591 ips 2024-04-12T10:16:53.196 VDF 1: Avg iters per intermediate: 512 2024-04-12T10:16:53.196 2024-04-12T10:16:53.196 VDF 1: Proof stopped 2024-04-12T10:16:53.209 VDF 1: Proof stopped 2024-04-12T10:16:53.215 VDF 1: Proof stopped 2024-04-12T10:16:53.218 VDF 1: Stopped at iters=34498575 2024-04-12T10:16:53.218 Bad data size after stop: -1 2024-04-12T10:16:53.218 VDF 1: Connection closed 2024-04-12T10:16:53.218 VDF 2: Stop requested 2024-04-12T10:16:53.218 2024-04-12T10:16:53.218 VDF 2: 34498096 HW iters done in 33s, HW speed: 1015540 ips 2024-04-12T10:16:53.218 VDF 2: 4068506 SW iters done in 70s, SW speed: 57520 ips 2024-04-12T10:16:53.218 VDF 2: Avg iters per intermediate: 502 2024-04-12T10:16:53.218 2024-04-12T10:16:53.280 VDF 2: Proof stopped 2024-04-12T10:16:53.303 VDF 2: Proof stopped 2024-04-12T10:16:53.311 VDF 2: Stopped at iters=34498096 2024-04-12T10:16:53.311 VDF 2: Connection closed 2024-04-12T10:16:53.311 Connecting to 127.0.0.1:8000 2024-04-12T10:16:53.311 VDF 0: Connected to timelord, waiting for challenge 2024-04-12T10:16:53.311 Connecting to 127.0.0.1:8000 2024-04-12T10:16:53.312 VDF 1: Connected to timelord, waiting for challenge 2024-04-12T10:16:53.312 Connecting to 127.0.0.1:8000 2024-04-12T10:16:53.312 VDF 2: Connected to timelord, waiting for challenge 2024-04-12T10:16:53.476 VDF 0: Allocating intermediate values, total 2 * 4096


- `too much work for VDF aux thread` warning, Chris indicated that this warning is nothing to concern over but can you provide some insights as to what it means? This error recurs constantly in the timelord output:

2024-04-12T10:17:05.461 VDF 1: Starting proof thread 0 for iters=10216000, length=4196000 [checkpoint] 2024-04-12T10:17:05.462 VDF 2: Starting proof thread 0 for iters=10216000, length=4196000 [checkpoint] 2024-04-12T10:17:06.367 VDF 0: Starting proof thread 1 for iters=11136000, length=2784000 [checkpoint] 2024-04-12T10:17:06.841 VDF 1: Starting proof thread 1 for iters=11616000, length=1400000 [checkpoint] 2024-04-12T10:17:06.842 VDF 2: Starting proof thread 2 for iters=11616000, length=1400000 [checkpoint] 2024-04-12T10:17:07.323 VDF 0: Starting proof thread 3 for iters=12105191, length=969191 2024-04-12T10:17:07.324 VDF 1: Starting proof thread 3 for iters=12105191, length=489191 2024-04-12T10:17:07.324 VDF 2: Starting proof thread 4 for iters=12105191, length=489191 2024-04-12T10:17:07.784 VDF 1: Warning: too much work for VDF aux threads; qlen=4 2024-04-12T10:17:07.836 VDF 2: Warning: too much work for VDF aux threads; qlen=4 2024-04-12T10:17:07.844 VDF 1: Warning: too much work for VDF aux threads; qlen=8 2024-04-12T10:17:07.883 VDF 0: Warning: too much work for VDF aux threads; qlen=4 2024-04-12T10:17:07.911 VDF 0: Warning: too much work for VDF aux threads; qlen=8 2024-04-12T10:17:07.951 VDF 2: Warning: too much work for VDF aux threads; qlen=8 2024-04-12T10:17:07.973 VDF 0: Warning: too much work for VDF aux threads; qlen=16 2024-04-12T10:17:08.011 VDF 2: Warning: too much work for VDF aux threads; qlen=16 2024-04-12T10:17:08.060 VDF 1: Warning: too much work for VDF aux threads; qlen=16 2024-04-12T10:17:08.406 VDF 2: Starting proof thread 1 for iters=13196000, length=1580000 [checkpoint] 2024-04-12T10:17:08.411 VDF 1: Starting proof thread 10 for iters=13196000, length=1580000 [checkpoint] 2024-04-12T10:17:08.543 VDF 2: Warning: too much work for VDF aux threads; qlen=32 2024-04-12T10:17:08.559 VDF 1: Warning: too much work for VDF aux threads; qlen=32 2024-04-12T10:17:08.580 VDF 0: Warning: too much work for VDF aux threads; qlen=32 2024-04-12T10:17:08.835 VDF 1: Warning: too much work for VDF aux threads; qlen=64 2024-04-12T10:17:08.862 VDF 2: Warning: too much work for VDF aux threads; qlen=64 2024-04-12T10:17:08.924 VDF 2: Starting proof thread 12 for iters=13723667, length=527667 2024-04-12T10:17:08.937 VDF 1: Starting proof thread 8 for iters=13723667, length=527667



### Version

2.2.1

### What platform are you using?

Linux

### What ui mode are you using?

CLI

### Relevant log output

_No response_

This issue is still present in 2.4.4, now the log spam in the chia client is even worse :/

This is only about half of the spam from a single instance of the shutdown:

2024-11-27T12:08:17.718 2.4.4 timelord chia.timelord.timelord   : WARNING  Too late to infuse block
2024-11-27T12:08:17.718 2.4.4 timelord chia.timelord.timelord   : WARNING  Too late to infuse block
2024-11-27T12:08:17.718 2.4.4 timelord asyncio                  : WARNING  socket.send() raised exception.
2024-11-27T12:08:17.738 2.4.4 timelord chia.timelord.timelord   : ERROR    Error while handling message: Traceback (most recent call last):
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 884, in _manage_chains
  File "chia/timelord/timelord.py", line 432, in _submit_iterations
  File "asyncio/streams.py", line 359, in drain
  File "chia/timelord/timelord.py", line 212, in _stop_chain

Chia-Network / chia-blockchain

[Bug] ASIC Timelord Log Spam and Output Error #17863

What happened?