Chia-Network / chia-blockchain

Chia blockchain python implementation (full node, farmer, harvester, timelord, and wallet)
Apache License 2.0
10.82k stars 2.03k forks source link

[Bug] Invalid Partial displayed in GUI with no logical explanation. #16073

Closed Coyote-UK closed 11 months ago

Coyote-UK commented 1 year ago

What happened?

I rebooted my farming computer and 3 hours later noticed an 'Invalid Partial' displayed in the GUI (see screenshot).

image

An initial assessment suggested this was coming from the pool, and even possibly the result of a Duplicate Partial. Further investigation demonstrated that there had been no Duplicate Partials submitted to the pool since the farmer had been rebooted, and no "Invalid" response could be found on the pool side.

image

The next best guess is that the following process occurred:

  1. pool tells the farmer service the difficulty it expects.
  2. farmer passes that on to the harvester.
  3. harvester receives signage point, finds proof, checks that proof against difficulty, and only sends partial good enough for the difficulty to the farmer.
  4. farmer rechecks that partial difficulty is good enough for pool. in this case, it's not good enough (even though the harvester believed it was) and thus the farmer drops it.

Since the farmer was stable, no changes had occurred to any of the parameters for at least 3 hours, and the pool difficulty had been static for several weeks, if this is true it suggests a bug in the farmer/harvester.

Version

2.0.0rc4

What platform are you using?

Windows

What ui mode are you using?

GUI

Relevant log output

2023-08-16T13:53:54.856 farmer chia.plot_sync.receiver    : WARNING  _process: node_id 4291051168be3c00318722098aaab49a39ed3df6ae24ff83320c86638739d0be, InvalidIdentifierError Invalid identifier: Actual {'message_id': 0, 'sync_id': 1692190405, 'timestamp': 1692190434}, Expected {'message_id': 1, 'sync_id': 1692190405, 'timestamp': 1692190434}
Coyote-UK commented 1 year ago

Following an upgrade to RC5 this morning I have a further example of an unexplained Invalid Partial. This occurred at least 2 hours after the farmer was rebooted & no duplicate partial has been recorded by either the pool or the log.

ChiaMineJP commented 1 year ago

The count of invalid_partials is incremented when:

  1. A proof is found but it doesn't pass the difficulty check for the pool. If this happens in your environment, you would have a log entry below: INFO Proof of space not good enough for pool ...
  2. A partial is sent but the response from the pool is not parsed correctly(Even the client cannot see whether the response is ok or not)
    If this happens, you would have a log entry below: ERROR Invalid response from harvester: ...
  3. A partial is sent but the response from the pool contains error code other than TOO_LATE(2).
    In this case you would see a log entry below: ERROR Error in pooling: ...
  4. An exception is raised while sending a partial to the pool In this case you would see a log entry below: ERROR Error connecting to pool:

I suspect case 1. for your case because the log appears only when log level to output is INFO while the default log level is WARNING. Please set the log level to INFO in your config.yaml like this and check the debug.log if another invalid partials are observed.: image

Coyote-UK commented 1 year ago

Hi

I was running my log at INFO so was able to search through for the messages you highlighted.

I found: 2023-08-17T12:47:27.650 farmer chia.farmer.farmer : INFO Proof of space not good enough for pool https://xch.spacefarmers.io: 50

The pool difficulty has been static for several weeks, whilst I have been testing various pre-releases with the compression enabled, and the pool admins have confirmed that nothing was presented to the pool.

As this appears to be contained within the farmer/harvester can you help me understand what the underlying cause would be. I cannot see any other indicators in the log file (see snippet below)

2023-08-17T12:47:15.345 wallet chia.wallet.wallet_blockchain: INFO Peak set to: 4099741 timestamp: 1692272793 2023-08-17T12:47:15.914 harvester chia.harvester.harvester: INFO _plot_refresh_callback: event started, loaded 0, removed 0, processed 0, remaining 2471, duration: 0.00 seconds, total plots: 2471 2023-08-17T12:47:16.277 harvester chia.harvester.harvester: INFO _plot_refresh_callback: event done, loaded 0, removed 0, processed 2471, remaining 0, duration: 0.23 seconds, total plots: 2471 2023-08-17T12:47:19.439 full_node chia.full_node.full_node: INFO Finished signage point 16/64: CC: 207b11d3b2d3e424c531c50bc71aafd2253519c1d8080daa9c195a24de1ab6c0 RC: 2cd262a7fd7421198cb902ee635c74601b25c2d547c706928dea49129750d20a 2023-08-17T12:47:25.625 full_node chia.full_node.full_node: INFO Added unfinished_block 093f758f5705c16f89678e37e6bc73789733941184a8424b2ec813503ae94b94, not farmed by us, SP: 16 farmer response time: 6.0315, Pool pk xch1nfyk5q74zsgdrhcy89jdava6cu44v3j2ad467fv6hm50czrqu0dqd4ccqj, validation time: 0.0210 seconds, pre_validation time 0.1009, cost: 588556165, percent full: 5.351% 2023-08-17T12:47:27.646 harvester chia.harvester.harvester: WARNING Looking up qualities on Q:\C5\plot-k32-c05-2023-06-14-11-26-0352fcc5e3dedc8ac87f86668679ddbef1ded2eaaac3c9c233def976d1f6d3bb.plot took: 8.199295997619629. This should be below 5 seconds to minimize risk of losing rewards. 2023-08-17T12:47:27.647 harvester chia.harvester.harvester: INFO 3 plots were eligible for farming a032302a3d... Found 1 proofs. Time: 8.19930 s. Total 2471 plots 2023-08-17T12:47:27.650 farmer chia.farmer.farmer : INFO Proof of space not good enough for pool https://xch.spacefarmers.io: 50 2023-08-17T12:47:28.190 full_node chia.full_node.full_node: INFO Finished signage point 17/64: CC: 953ff0e23b5dd04f5c9a99b2d6b2dc7389a53f6ae0f85d1812e656858e8f739f RC: c0315031d600e0094b03a693acb7b2f4d5dc8757536b842677f4da67a0c7fab2 2023-08-17T12:47:28.774 harvester chia.harvester.harvester: INFO 3 plots were eligible for farming a032302a3d... Found 0 proofs. Time: 0.57667 s. Total 2471 plots 2023-08-17T12:47:30.086 full_node chia.full_node.full_node: INFO Added unfinished_block 3af34307529d13cf296e49e556557e7825399e577445c6c63a3f6578e6b6bac7, not farmed by us, SP: 16 farmer response time: 10.5320, Pool pk xch182d6s8mf82k9hfmmc8jzla2lmfxt426830d3xq44l0ny8x8jwtxswru4he, validation time: 0.0180 seconds, pre_validation time 0.0800, cost: 588556165, percent full: 5.351% 2023-08-17T12:47:30.316 full_node chia.full_node.full_node: INFO Added unfinished_block 1e95e17c1aa89bcb715df3afd04c193456e93e3d4df7bdd90f04fe0684ace020, not farmed by us, SP: 17 farmer response time: 1.9839, Pool pk xch1jp6frj3ecddur7dxak3n7lq0j75ltquh2zyd44epdu0d6704y2hqyky5hf, validation time: 0.0220 seconds, pre_validation time 0.0989, cost: 588556165, percent full: 5.351%

Coyote-UK commented 1 year ago

From the pool (There is a 1 hour time difference in our time zones)

xch.spacefarmers.io 82.xxx.xxx.147 - - [17/Aug/2023:13:44:43 +0200] "POST /partial HTTP/1.1" 200 5440 "-" "Chia Blockchain v.2.0.0rc5" xch.spacefarmers.io 82.xxx.xxx.147 - - [17/Aug/2023:13:45:20 +0200] "POST /partial HTTP/1.1" 200 5408 "-" "Chia Blockchain v.2.0.0rc5" xch.spacefarmers.io 82.xxx.xxx.147 - - [17/Aug/2023:13:49:01 +0200] "GET /farmer HTTP/1.1" 200 5662 "-" "Python/3.9 aiohttp/3.8.4" xch.spacefarmers.io 82.xxx.xxx.147 - - [17/Aug/2023:13:50:36 +0200] "POST /partial HTTP/1.1" 200 5408 "-" "Chia Blockchain v.2.0.0rc5" xch.spacefarmers.io 82.xxx.xxx.147 - - [17/Aug/2023:13:54:13 +0200] "GET /farmer HTTP/1.1" 200 5663 "-" "Python/3.9 aiohttp/3.8.4"

So nothing at the time of that log entry.

ChiaMineJP commented 1 year ago

If a proof cannot pass the dificullty check, a partial won't be sent to a pool. So it's normal that the pool didn't receive any http request from your client. This case just suggests you that "maybe" a pool difficulty is a bit high for your environment. (Oh wait, invalid partials was only 0.7% in your environment. it seems the difficulty is correctly setup for you)

This is usually not a problem because it may happen on every signage points you receive. That's why the log level is set to INFO.

Perhaps there could be more suitable terminology for this scenario than "Invalid Partials." The term "Invalid Partials" tends to cause unnecessary concern among individuals, as it may imply issues with your configuration.

Ron-ski commented 1 year ago

The term "Invalid Partials" tends to cause unnecessary concern among individuals, as it may imply issues with your configuration

It certainly does, I get a few and I've no idea why, or what to look for until now.

ChiaMineJP commented 1 year ago

Alright, please leave this ticket open. I'll initiate a pull request to differentiate between "low" quality partials that don't meet the pool's difficulty criteria and other types of invalid partials.

wjblanke commented 11 months ago

This is fixed in main. we still need to rev the gui tag though. thanks for the report!