SignagePoints: Fix wrong handling of fork events

* Add test case for network fork * Fix logic to handle this case properly Fixes: #116 Should result in less false alarms.
martomi · May 17, 2021 · fb701fa · fb701fa
1 parent 41f2c40
commit fb701fa
Show file tree

Hide file tree

Showing 3 changed files with 40 additions and 19 deletions.
diff --git a/src/chia_log/handlers/util/calculate_skipped_signage_points.py b/src/chia_log/handlers/util/calculate_skipped_signage_points.py
@@ -5,6 +5,7 @@
 
 roll_over_point = 64
 expected_diff_seconds = 9
+smallest_expected_diff_seconds = 7
 
 
 def calculate_skipped_signage_points(
@@ -20,22 +21,6 @@ def calculate_skipped_signage_points(
     diff_id_roll = (roll_over_point - prev_id) + curr_id
     diff_seconds = (curr_ts - prev_ts).seconds
 
-    # This is hacky addition to prevent false alarms for some network-wide issues that
-    # aren't necessarily related to the local node. See "testNetworkScramble" test case.
-    # Signage points are expected approx every 8-10 seconds. If a point was skipped for real
-    # then we expect the time difference to be at least 2*8 seconds. Otherwise it's flaky event.
-    # Update: Too fast blocks are leading to forks in the network. A fork is when 1 block gets
-    # reversed from the blockchain. When that happens, the full node clears all the signage points
-    # from the whole slot, and re-adds them. This is what happens here. We can invalidate the calculation.
-    if diff_seconds < expected_diff_seconds * 1.5:
-        if diff_id != 1 and diff_id_roll != 1:
-            valid = False
-            logging.debug(
-                f"Probably out of order signage point IDs {prev_id} and {curr_id} "
-                f"with timestamps {prev_ts} and {curr_ts}"
-            )
-        return valid, 0
-
     one_roll_duration = roll_over_point * expected_diff_seconds
 
     roll_count = round(diff_seconds / one_roll_duration)
@@ -46,6 +31,17 @@ def calculate_skipped_signage_points(
     distance_to_expected_roll = abs(expected_diff_id - diff_id_roll)
 
     if distance_to_expected < distance_to_expected_roll:
-        return valid, (diff_id + roll_over_point * roll_count) - 1
-
-    return valid, (diff_id_roll + roll_over_point * roll_count) - 1
+        skipped = (diff_id + roll_over_point * roll_count) - 1
+    else:
+        skipped = (diff_id_roll + roll_over_point * roll_count) - 1
+
+    # Handle possible bursts of shuffled signage points resulting from a fork
+    upper_bound_expected_diff_id = round(diff_seconds / smallest_expected_diff_seconds)
+    if skipped > upper_bound_expected_diff_id:
+        valid, skipped = False, 0
+        logging.debug(
+            f"Probably out of order signage point IDs {prev_id} and {curr_id} "
+            f"with timestamps {prev_ts} and {curr_ts}"
+        )
+
+    return valid, skipped
diff --git a/tests/chia_log/handlers/test_finished_signage_point_handler.py b/tests/chia_log/handlers/test_finished_signage_point_handler.py
@@ -58,6 +58,16 @@ def testNetworkScramble(self):
             events = self.handler.handle(log)
             self.assertEqual(len(events), 0)
 
+    def testNetworkFork(self):
+        """Cover a use-case of a network fork combined with some delays between signage points.
+        See the network_fork.txt for reference. This is taken from a real-world event."""
+        with open(self.example_logs_path / "network_fork.txt", encoding="UTF-8") as f:
+            logs = f.readlines()
+
+        for log in logs:
+            events = self.handler.handle(log)
+            self.assertEqual(len(events), 0)
+
 
 if __name__ == "__main__":
     unittest.main()
diff --git a/tests/chia_log/logs/finished_signage_point/network_fork.txt b/tests/chia_log/logs/finished_signage_point/network_fork.txt
@@ -0,0 +1,15 @@
+2021-05-13T22:12:25.148 full_node chia.full_node.full_node: INFO     ⏲️  Finished signage point 60/64:
+2021-05-13T22:12:35.081 full_node chia.full_node.full_node: INFO     ⏲️  Finished signage point 61/64:
+2021-05-13T22:12:41.911 full_node chia.full_node.full_node: INFO     ⏲️  Finished signage point 62/64:
+2021-05-13T22:12:49.784 full_node chia.full_node.full_node: INFO     ⏲️  Finished signage point 63/64:
+2021-05-13T22:12:58.453 full_node chia.full_node.full_node: INFO     ⏲️  Finished sub slot, SP 64/64,
+2021-05-13T22:13:07.659 full_node chia.full_node.full_node: INFO     ⏲️  Finished signage point 1/64:
+2021-05-13T22:13:14.053 full_node chia.full_node.full_node: INFO     ⏲️  Finished signage point 2/64:
+2021-05-13T22:13:42.341 full_node chia.full_node.full_node: INFO     ⏲️  Finished sub slot, SP 64/64,
+2021-05-13T22:13:50.884 full_node chia.full_node.full_node: INFO     ⏲️  Finished signage point 1/64:
+2021-05-13T22:13:58.247 full_node chia.full_node.full_node: INFO     ⏲️  Finished signage point 2/64:
+2021-05-13T22:14:06.288 full_node chia.full_node.full_node: INFO     ⏲️  Finished signage point 3/64:
+2021-05-13T22:14:14.181 full_node chia.full_node.full_node: INFO     ⏲️  Finished signage point 4/64:
+2021-05-13T22:14:22.166 full_node chia.full_node.full_node: INFO     ⏲️  Finished signage point 5/64:
+2021-05-13T22:14:30.104 full_node chia.full_node.full_node: INFO     ⏲️  Finished signage point 6/64:
+2021-05-13T22:14:38.398 full_node chia.full_node.full_node: INFO     ⏲️  Finished signage point 7/64: