[Bug] ASIC Timelord Log Spam and Output Error

[BrandtH22]

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):

1. Log spam and associated socket error (chia logs)
2. 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