search

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] "Don't have signage point" although I have it, an issue with chia 1.3.x #11294

Open alnuweiri opened 2 years ago

alnuweiri commented 2 years ago

What happened?

I am seeing in the log a lot of "INFO Don't have signage point {'challenge_hash': ......." although if you look at the logs it seems that I already have the signage point. In the example I attached below you can see the following:

INFO Finished signage point 22/64:

So I assume that I have the signage point 22 but after that, I see this log

INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}

I get this message a few times, then I get this log again:

INFO Finished signage point 22/64:

I am wondering what is happening here, and why I am getting the signage point two times. I noticed this behavior since I updated Chia to 1.3.x

I am getting a lot of this example although I have a high-end PC with a fast NVMe disk.

Version

1.3.4

What platform are you using?

Windows

What ui mode are you using?

GUI

Relevant log output

2022-04-24T12:50:39.811 full_node chia.full_node.full_node: INFO       Finished signage point 22/64: CC: defd5e41497c85a0cfdcd042c8ad7dfb5c77c234de86aa5d4fc7508dfad9e4b8 RC: de34832758e810e38484aca97c90888607ebd4b72631ec61af8f7f3c03b51125 
2022-04-24T12:50:39.987 full_node chia.full_node.full_node: INFO      Updated peak to height 1882139, weight 4008574880, hh 3a62e328d4702d3732b86b6ceedd0a23d529d0f460e2fcd6a995b5aad6f6fbf4, forked at 1882138, rh: a19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d, total iters: 7425093591331, overflow: False, deficit: 1, difficulty: 2352, sub slot iters: 135266304, Generator size: 112532, Generator ref list size: 0
2022-04-24T12:50:40.008 full_node chia.full_node.mempool_manager: INFO     Size of mempool: 265 spends, cost: 108057978195 minimum fee rate (in FPC) to get in for 5M cost tx: 0
2022-04-24T12:50:40.020 harvester chia.harvester.harvester: INFO     2 plots were eligible for farming b5ad7b6335... Found 0 proofs. Time: 0.19785 s. Total 2533 plots
2022-04-24T12:50:40.020 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.039 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.039 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.059 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.065 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.070 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.072 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.072 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.090 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.161 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.171 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.187 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.195 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.201 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.205 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.205 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.222 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.228 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.235 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.238 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.238 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.257 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.266 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.271 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.271 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.282 full_node chia.full_node.full_node: INFO     Don't have signage point {'challenge_hash': '0xb5ad7b633518fcd89031ee6ac9dced0f141c340052f7d97fc7be49a36ac8f9ee',
 'index_from_challenge': 22,
 'last_rc_infusion': '0xa19b123830c714ba645e755404180d9d1faaeb5aca2382731a894ba8cd69c23d'}
2022-04-24T12:50:41.368 wallet chia.wallet.wallet_blockchain: INFO     Peak set to: 1882139 timestamp: 1650797408
2022-04-24T12:50:41.432 full_node chia.full_node.full_node: INFO       Finished signage point 22/64: CC: defd5e41497c85a0cfdcd042c8ad7dfb5c77c234de86aa5d4fc7508dfad9e4b8 RC: de34832758e810e38484aca97c90888607ebd4b72631ec61af8f7f3c03b51125 
2022-04-24T12:50:41.474 harvester chia.harvester.harvester: INFO     2 plots were eligible for farming b5ad7b6335... Found 0 proofs. Time: 0.03301 s. Total 2533 plots
2022-04-24T12:50:48.178 full_node chia.full_node.full_node: INFO       Finished signage point 23/64: CC: 3b40b2336deec87f4f2064ce4b99dfe457bd00083a184dd0b796c8188f1cfa6a RC: 487c208f0a4b16465f27e9ba449937a83e04f14f356765f8f4ef43fcf826bb73
alnuweiri commented 2 years ago

Also it is worth mentioning that when this happens I will get twice this message in the log "XX plots were eligible for farming..." where the second time it's always a much faster lookup time for the plots: 

2022-04-25T00:20:57.985 full_node chia.full_node.full_node: INFO       Finished signage point 60/64: CC: 5805e47d0e302987d1c006034ae9fa9534dd536e1831c76a1b82e119cc41d193 RC: fddbe670cccd7914646a221495f19e911099716fb74eeb6a0c6073631c4fd281 
2022-04-25T00:20:58.117 full_node chia.full_node.full_node: INFO      Updated peak to height 1884395, weight 4013880992, hh 83b9c07e24c0f46d025379a48596e46d51119b46e26767c94d794838383def99, forked at 1884394, rh: 969fbfd2cbf18224ebf0945e94ae928a94c82b27e698bcb15211baecc8635796, total iters: 7434506884419, overflow: False, deficit: 0, difficulty: 2352, sub slot iters: 135266304, Generator size: 73067, Generator ref list size: 0
2022-04-25T00:20:58.124 full_node chia.full_node.full_node: INFO       Finished signage point 60/64: CC: 5805e47d0e302987d1c006034ae9fa9534dd536e1831c76a1b82e119cc41d193 RC: fddbe670cccd7914646a221495f19e911099716fb74eeb6a0c6073631c4fd281 
2022-04-25T00:20:58.137 full_node chia.full_node.mempool_manager: INFO     Size of mempool: 200 spends, cost: 107327646146 minimum fee rate (in FPC) to get in for 5M cost tx: 0
2022-04-25T00:20:58.195 harvester chia.harvester.harvester: INFO     6 plots were eligible for farming 25002045c2... Found 0 proofs. Time: 0.19908 s. Total 2533 plots
2022-04-25T00:20:58.203 harvester chia.harvester.harvester: INFO     6 plots were eligible for farming 25002045c2... Found 0 proofs. Time: 0.04967 s. Total 2533 plots
alnuweiri commented 2 years ago

After investigating more on the issue, I found that the problem is caused by receiving the signage point twice for many of the signage points. This problem is affecting many people, for example, there is one post on Reddit where a person found two proof in less than a minute but received only one reward, after checking his log file I found actually that reason is that he got the signage point twice and the harvester checked twice for the proof. Also, issue #10827 is caused by the same problem. Moreover, I guess some of the people who recently reported a longer lookup time for the plots are getting this problem because the harvester is checking for proof twice in less than 1 second when they get the signage point twice.

alnuweiri commented 1 year ago

This problem still exists even after updating to Chia 1.6.2 on Windows!

github-actions[bot] commented 1 year ago

This issue has not been updated in 14 days and is now flagged as stale. If this issue is still affecting you and in need of further review, please comment on it with an update to keep it from auto closing in 7 days.

alnuweiri commented 1 year ago

Still exists

MumfMeisterT commented 1 year ago

Could you put your log into DEBUG mode and provide us with the full log?

alnuweiri commented 1 year ago

I will do that in few days!

github-actions[bot] commented 1 year ago

This issue has not been updated in 14 days and is now flagged as stale. If this issue is still affecting you and in need of further review, please comment on it with an update to keep it from auto closing in 7 days.

alnuweiri commented 1 year ago

debug2.log

Here is the full log file with Debug level!

To find the problem please search for "Don't have signage point" you will find a few hits, check the first one, and you will find before it "Finished signage point 5/64" 2023-03-05T17:21:01.091 full_node chia.full_node.full_node: INFO Finished signage point 5/64: CC: ef7314e3502d06a2989d40a849a69f642e4cb2d90f83447e63c1d24d3231732c RC: 5f85479fa9694c5d58fa8b02cda500a10a823bdff2a87bd41ba3cf445b041f7c

and some lines after it again "Finished signage point 5/64"

2023-03-05T17:21:01.816 full_node chia.full_node.full_node: INFO Finished signage point 5/64: CC: ef7314e3502d06a2989d40a849a69f642e4cb2d90f83447e63c1d24d3231732c RC: 5f85479fa9694c5d58fa8b02cda500a10a823bdff2a87bd41ba3cf445b041f7c

You can see in the logs this 2023-03-05T17:21:01.459 full_node chia.full_node.full_node_store: DEBUG Reverting 5 13790390190080 13790389232797

and

2023-03-05T17:21:01.930 farmer chia.farmer.farmer : DEBUG Duplicate signage point 5

alnuweiri commented 1 year ago

debug4.log debug4.log.zip

Here is another different example, I have uploaded a part of the log file as .log and the full file is uploaded as .zip because of the file size limitation on GitHub.

Here you will find this case: "Finished signage point 24/64" and then "Finished signage point 25/64" and after a few seconds you will see again "Finished signage point 24/64" and "Finished signage point 25/64"

2023-03-05T17:03:44.599 full_node chia.full_node.full_node: INFO Finished signage point 24/64: CC: ab9275652e0a780a580cf9507933171f6c128dc1e0ba023e30ca93e20e16d3da RC: 3b7fc13240ab1fe72601e6508af9ecfef9b00dbc4b98faa147a4a1b9481f192a

2023-03-05T17:03:53.532 full_node chia.full_node.full_node: INFO Finished signage point 25/64: CC: 8baa84219dd71a59272e3a1921cf52283e03da956a359abcf6b01308fcc25e6a RC: b9268b3c6d443173269d166790f91a145453a41261425b78b2d8d53c8f3a807f

And again after few seconds

2023-03-05T17:04:05.812 full_node chia.full_node.full_node: INFO Finished signage point 24/64: CC: ab9275652e0a780a580cf9507933171f6c128dc1e0ba023e30ca93e20e16d3da RC: 8dfdab7ebd326be64f78b05e2b563f116751bb0427a829b5eee4875591c336fc

2023-03-05T17:04:14.568 full_node chia.full_node.full_node: INFO Finished signage point 25/64: CC: 8baa84219dd71a59272e3a1921cf52283e03da956a359abcf6b01308fcc25e6a RC: 44b5a655431d64dc113993139c674fad9e0440494444a388d072e1f387f7c318

However, in this case, you can notice that "RC:" between the first "signage point 24" and the second "signage point 24" is different, also it's different between the first "signage point 25" and the second one.

Also, you can see in the logs these lines

2023-03-05T17:03:57.075 full_node chia.full_node.full_node_store: DEBUG Reverting 24 13790140170240 13790138150366 2023-03-05T17:03:57.076 full_node chia.full_node.full_node_store: DEBUG Reverting 25 13790142464000 13790138150366

alnuweiri commented 1 year ago

@MumfMeisterT

MumfMeisterT commented 1 year ago

Thank you @alnuweiri - Assigning this ticket out to look through the logs and get back to you.

wjblanke commented 1 year ago

Thanks for the logs, I took a look and it seems like somewhere in the network, signage points and a block got out of order. The block arrived after the 24/25 signage points instead of before:

2023-03-05T17:03:57.070 full_node chia.full_node.full_node: INFO Updated peak to height 3336842, weight 6824429736, hh f95b226c287a9f6a6616d58216b4fba26acb14566898cc3ca9dbb38a71db9ce5, forked at 3336841, rh: 804a5694ad517b824323d60458fd67db29d9cb1b8ef55f229044647107545765, total iters: 13790138150366, overflow: False, deficit: 0, difficulty: 1976, sub slot iters: 146800640, Generator size: No tx, Generator ref list size: No tx

This changed the reward chain, so signage points 24 and 25 were invalid, thats why they were reverted back to iter 13790138150366.

Then new signage points 24 and 25 with the altered reward chain arrived.

Now, there is an issue here. I don't think the farmer should need to do a plot lookup again (which I think is your complaint). All that has changed is the reward chain. So maybe we can cache the lookup to avoid that overhead in case this happens. Leaving this issue open for that improvement.