[Bug] Impossible farmer response time for unfinished_blocks on SP: 0 in full_node logs

[scrutinously]

What happened?

With info level logs running on a full node, the "Added unfinished block" entry will periodically provide an impossible number for "farmer response time" on entries for SP: 0. This can be seen either by parsing for results that are greater than a reasonable number of seconds (almost always returning a SP: 0 entry) or by specifically parsing for SP: 0 entries.

for example: cat ~/.chia/mainnet/log/debug.log.1 ~/.chia/mainnet/log/debug.log | tr -d ',' | awk '/farmer response time/ {if (2000 < $17) {print}}' will likely return every single SP: 0 entry from the latest 2 log files.

Version

1.2.11

What platform are you using?

Linux

What ui mode are you using?

CLI

Relevant log output

2022-06-09T20:10:30.768 full_node chia.full_node.full_node: INFO     Added unfinished_block 34c2247199e56e3d63f3026a15d3f244afb7aa86c2b2746115d3b1057806ab81 not farmed by us SP: 0 farmer response time: 477181.2416 Pool pk xch1vfvaczrhchrn89u8zr8vdauj37wwh8mv0m8zzukq8y2jevllsq6q9syz0a validation time: 0.0479 seconds pre_validation time 0.0211 cost: 216585154 percent full: 1.969%
2022-06-09T21:00:11.019 full_node chia.full_node.full_node: INFO     Added unfinished_block f9d5bcacd0619f01fe2ce835f3b0c0191f1e506553913b398f86ce97c30d75f9 not farmed by us SP: 0 farmer response time: 480161.5054 Pool pk xch1f0ryxk6qn096hefcwrdwpuph2hm24w69jnzezhkfswk0z2jar7aq5zzpfj validation time: 0.0641 seconds cost: 0 percent full: 0.0%
2022-06-09T21:10:04.396 full_node chia.full_node.full_node: INFO     Added unfinished_block 4f996dcba527268a6be6b8e3de1a0cec178c75768bd566fc4d1fb3e3e5789000 not farmed by us SP: 0 farmer response time: 480754.7646 Pool pk xch19ml2wgr5jxa62nwtjg8a9lcz6pkulx34wr7ywc76dka6w2ryglnqckwmcc validation time: 0.1228 seconds pre_validation time 0.0506 cost: 1128925532 percent full: 10.263%
2022-06-09T21:10:06.374 full_node chia.full_node.full_node: INFO     Added unfinished_block d837865ae499f310b6071a5c68a9ccb886f6c2ed6a9bb3f984b6356f090e6f02 not farmed by us SP: 0 farmer response time: 480756.7417 Pool pk xch1u6a8wkcypxlx7quyz0cethzshkctu6uznflwgd59g7pfsme85vrsxr3cql validation time: 0.1232 seconds pre_validation time 0.0520 cost: 1128925532 percent full: 10.263%
2022-06-09T21:10:13.131 full_node chia.full_node.full_node: INFO     Added unfinished_block 8067d36fbe1dbe2153b0899934ae66ec9f3b69d1323cb30cb0ad45bfcb9e71dd not farmed by us SP: 0 farmer response time: 480763.5553 Pool pk xch1g0cl3yah0afjaze54ehnach8q8d0py3e736nj50cw27r7tz994ksr279cq validation time: 0.0812 seconds pre_validation time 0.0435 cost: 1161228466 percent full: 10.557%

[wallentx]

Same on 1.3.5

[alnuweiri]

I can confirm on my node on Windows with Chia 1,3,5

2022-06-10T23:05:23.165 full_node chia.full_node.full_node: INFO Added unfinished_block e946364b1a6749de50ae624fb73cba97f1368354ea6789e00a699ce88ecf6822, not farmed by us, SP: 0 farmer response time: 3798.2807, Pool pk xch1yp8tqnnsjrttdtnrqftr4d3fsrrj58pxgegspmsyc0kkny3vwuuqgwc36t, validation time: 0.0156 seconds, pre_validation time 0.0312, cost: 420761575, percent full: 3.825%
2022-06-10T23:05:23.988 full_node chia.full_node.full_node: INFO Added unfinished_block 6c7991c3a642ba436d82979e71dd4642726d9515af3f384a64054c62e90861d4, not farmed by us, SP: 0 farmer response time: 3799.0997, Pool pk xch156dc3shjj2q05vag86eae20ctx6t3j2c3h36vucqreune9hprt0szxqf2m, validation time: 0.0122 seconds, pre_validation time 0.0303, cost: 420761575, percent full: 3.825%
2022-06-10T23:35:24.504 full_node chia.full_node.full_node: INFO Added unfinished_block 003729a3a648baa963296db09065e0d368aeb95932f6feca189462661daacab8, not farmed by us, SP: 0 farmer response time: 5599.5961, Pool pk xch1lu4ksfxy8k8r4rumlqc6x70u3nzs6fdy7sclkzwl9ttd43hsgdwq3ds68l, validation time: 0.0460 seconds, pre_validation time 0.0230, cost: 995617848, percent full: 9.051%
2022-06-10T23:55:24.900 full_node chia.full_node.full_node: INFO Added unfinished_block 48b7f6439621e53367164d76fa10c52dbde61162e69cc1bf33561aa80f9dfe87, not farmed by us, SP: 0 farmer response time: 6800.0469, Pool pk xch1jp6frj3ecddur7dxak3n7lq0j75ltquh2zyd44epdu0d6704y2hqyky5hf, validation time: 0.0154 seconds, cost: 0, percent full: 0.0%

[emlowe]

There is a bug with SP 0 as it's not a signage point like the others, it's a special end of slot condition and so needs some other code. But this is strictly a logging bug and doesn't affect anything else.

[emlowe]

Fixed in 1.6.2 by #136555