chia-blockchain 1.1.7 is dropping logs

[hortocam]

Just updated to 1.1.7 and it looks like something is causing logs to be queued up or dropped.

Getting multiple notifications about missed SPs and missing farming challenges.

I can see the logs are jumbled and the SP messages aren’t there even though other messages refer to increasing SPs.

The harvester messages seem to come in batches out of normal sequence some of the time and other times it all seems synchronous as you’d expect.

[hortocam]

I wonder if it is due to the wallet sync?

The full node was synced and then I started farmer and wallet.

It’s subsided in the past 20 mins but was very flaky for about an hour.

[hortocam]

So this is more pronounced when the wallet is syncing or the node is doing a backtrack sync.

Once everything is synced, there are occasions where something holds up the finished sp logs and harvester logs for a few minutes. I will post log samples soon.

[hortocam]

delayed_signage_points.log

In this log fragment, you can see there's a delay of over one minute between signage points 48 and 49 - excerpted below:
2021-06-09T16:12:03.804 full_node chia.full_node.full_node: INFO ⏲️ Finished signage point 48/64: CC: 27f9d92e3d8da13cfdf0d80d52c0972090f738e6cecce5b56243a887ec081979 RC: 5887b5587f69b34a90201dd3f7c1c9b7a0c342456fa9088f43d54e9f18ca2fba

2021-06-09T16:13:19.943 full_node chia.full_node.full_node: INFO ⏲️ Finished signage point 49/64: CC: 7d9876991cce3fd7e710b73bda200e9cfb16eeaa01df32a1115ae1dd20319fa7 RC: 55c58a12deb6fefa037bb2e7170b6117cb055025a194931eb06eec1306663c9c

You can also see that after it catches up, it logs harvester/farming events out of order almost in batch:
2021-06-09T16:13:19.943 full_node chia.full_node.full_node: INFO ⏲️ Finished signage point 49/64: CC: 7d9876991cce3fd7e710b73bda200e9cfb16eeaa01df32a1115ae1dd20319fa7 RC: 55c58a12deb6fefa037bb2e7170b6117cb055025a194931eb06eec1306663c9c

2021-06-09T16:13:19.946 full_node chia.full_node.full_node: INFO ⏲️ Finished signage point 50/64: CC: 1e9ecaf27e92f8cd33706af28c9b6eb5850e9e4220f975dce28efbb15ddaa716 RC: 38b386ea80d1db879b4b934236bf56678775085dad3b3ac829201ee615fc84d0

2021-06-09T16:13:19.970 full_node chia.full_node.full_node: INFO Block validation time: 65.15160703659058, cost: 114326938, percent full: 1.039%

2021-06-09T16:13:20.030 harvester chia.harvester.harvester: INFO 0 plots were eligible for farming 12075b0a96... Found 0 proofs. Time: 0.02697 s. Total 51 plots

2021-06-09T16:13:20.044 harvester chia.harvester.harvester: INFO 0 plots were eligible for farming 12075b0a96... Found 0 proofs. Time: 0.00864 s. Total 51 plots

I have many examples of this happening. Sometimes it may be 2 or 3 SPs that appear to batch together. Other times it's more than 5.

This is causing ChiaDog to trigger events in time_since_last_farm_event.py.