Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[BUG] multiple new_signage_point spam, looks like malicious network attack #5410

Closed
dima-stefantsov opened this issue May 18, 2021 · 5 comments
Labels
bug Something isn't working

Comments

@dima-stefantsov
Copy link

Describe the bug
Every ~10 seconds I should be getting a new signage point to test my plots against it. Usually it works fine. But sometimes I get tens (10x+) signage points at the same time with no apparent reason. It leads to extra load and lookup timeouts.

To Reproduce
Steps to reproduce the behavior:

  1. Enable log level DEBUG
  2. Start farming
  3. Notice sometimes signage points appear not one-per-10sec, but extra in bursts
  4. Usually it will lead to multiple WARNINGs "Looking up qualities on ... .plot took: 35.1394734382629395. This should be below 5 seconds to minimize risk of losing rewards.", even though everything is fine with plots and disks

Expected behavior
Signage points should come one at a time, not in multiple bursts.

Screenshots

2021-05-18T13:23:15.682 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:23:15.683 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:23:16.691 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 1.0083022117614746 seconds
2021-05-18T13:23:23.063 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:23:23.064 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:23:24.079 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 1.0152833461761475 seconds
2021-05-18T13:23:30.696 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:23:30.696 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:23:31.707 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 1.0112948417663574 seconds
2021-05-18T13:23:38.829 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:23:38.830 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:23:40.849 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 2.01859974861145 seconds
2021-05-18T13:23:47.297 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:23:47.298 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:23:48.303 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 1.0048651695251465 seconds
2021-05-18T13:23:56.070 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:23:56.070 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:23:56.074 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.0039882659912109375 seconds
2021-05-18T13:24:05.284 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:24:05.284 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:24:05.288 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.003988981246948242 seconds
2021-05-18T13:24:17.498 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:24:17.498 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:24:17.501 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.0029909610748291016 seconds
2021-05-18T13:24:24.271 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:24:24.271 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:24:25.285 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 1.0135507583618164 seconds
2021-05-18T13:24:35.043 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:24:35.044 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:24:35.048 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.0039904117584228516 seconds
2021-05-18T13:24:41.798 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:24:41.799 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:24:43.830 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 2.031871795654297 seconds
2021-05-18T13:24:50.542 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:24:50.542 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:24:51.548 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 1.006087064743042 seconds
2021-05-18T13:25:03.614 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:03.614 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:04.623 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 1.0093183517456055 seconds
2021-05-18T13:25:09.800 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:09.801 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:09.806 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.004984855651855469 seconds
2021-05-18T13:25:20.217 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:20.218 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:20.221 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.002991199493408203 seconds

it was fine until this time.
now it somehow got 2 new_signage_point the same second:
2021-05-18T13:25:30.288 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:30.289 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:30.290 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:30.297 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:30.301 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.010969400405883789 seconds
2021-05-18T13:25:30.309 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:30.311 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.013964414596557617 seconds
2021-05-18T13:25:30.315 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.0059850215911865234 seconds

2 new_signage_point again less than 1 second later:
2021-05-18T13:25:30.291 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:31.292 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:31.293 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:31.296 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.0029921531677246094 seconds
2021-05-18T13:25:31.297 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:31.300 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.0029916763305664062 seconds

the very same second lots of new_signage_point spam incoming...
this is not normal!
2021-05-18T13:25:31.293 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.296 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.297 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.298 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.298 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.299 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.300 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.301 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.302 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.302 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.303 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.304 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.304 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.305 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.306 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.306 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.307 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.308 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.308 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:32.463 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.464 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.465 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.466 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.467 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.468 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.469 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.470 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.471 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.471 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.472 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.473 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.473 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.474 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.475 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.476 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.477 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.478 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:32.538 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07579874992370605 seconds
2021-05-18T13:25:32.538 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.0747992992401123 seconds
2021-05-18T13:25:32.539 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07480025291442871 seconds
2021-05-18T13:25:32.540 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07479619979858398 seconds
2021-05-18T13:25:32.541 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.0747992992401123 seconds
2021-05-18T13:25:32.542 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07479977607727051 seconds
2021-05-18T13:25:32.543 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07480096817016602 seconds
2021-05-18T13:25:32.544 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.0747992992401123 seconds
2021-05-18T13:25:32.545 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07480025291442871 seconds
2021-05-18T13:25:32.545 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07480025291442871 seconds
2021-05-18T13:25:32.546 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07480025291442871 seconds
2021-05-18T13:25:32.547 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07480096817016602 seconds
2021-05-18T13:25:32.548 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07579803466796875 seconds
2021-05-18T13:25:32.549 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07579708099365234 seconds
2021-05-18T13:25:32.550 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07579803466796875 seconds
2021-05-18T13:25:32.551 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07579612731933594 seconds
2021-05-18T13:25:32.553 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07679486274719238 seconds
2021-05-18T13:25:32.554 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07679438591003418 seconds
2021-05-18T13:25:33.885 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:33.886 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:33.886 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:33.887 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:33.888 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:34.905 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 1.018275499343872 seconds
2021-05-18T13:25:34.906 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:34.929 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:34.930 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:34.931 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.024932384490966797 seconds
2021-05-18T13:25:34.954 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.024932861328125 seconds
2021-05-18T13:25:34.955 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.024935245513916016 seconds
2021-05-18T13:25:38.072 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:38.073 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:38.076 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.0029921531677246094 seconds
2021-05-18T13:25:38.077 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:38.082 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.004987478256225586 seconds
2021-05-18T13:25:38.073 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:39.084 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:39.877 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:39.878 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:39.879 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:39.880 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:39.881 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:39.882 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:40.474 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:40.474 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:40.935 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:40.936 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:40.938 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:40.939 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:40.941 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:40.943 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:40.944 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:40.945 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:40.946 farmer farmer_server              : INFO     <- new_signage_point from peer full_node_hash_or_key 127.0.0.1
2021-05-18T13:25:41.006 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.0718083381652832 seconds
2021-05-18T13:25:41.007 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.07081055641174316 seconds
2021-05-18T13:25:41.008 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.06981277465820312 seconds
2021-05-18T13:25:41.009 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.06981325149536133 seconds
2021-05-18T13:25:41.010 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.0688169002532959 seconds
2021-05-18T13:25:41.011 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.06881570816040039 seconds
2021-05-18T13:25:41.012 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.06781864166259766 seconds
2021-05-18T13:25:41.012 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.06682181358337402 seconds
2021-05-18T13:25:41.013 farmer farmer_server              : DEBUG    Time taken to process new_signage_point from full_node_hash_or_key is 0.06682133674621582 seconds
2021-05-18T13:25:42.675 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:42.677 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:42.678 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:42.680 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:42.681 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:42.682 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:42.683 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:42.684 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:42.685 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key
2021-05-18T13:25:43.108 full_node full_node_server        : INFO     -> new_signage_point to peer 127.0.0.1 farmer_hash_or_key

Desktop (please complete the following information):

  • OS: Windows 10 Pro
  • OS Version/Flavor: 20H2 build 19042.985 (latest)
  • CPU: Intel(R) Core(TM) i7-6700K CPU @ 4.00GHz (4 cores 8 threads)
  • ~1Gbit internet, ~20ms ping to Europe
  • ~60 full node peers with max height, no problems with sync
  • blockchain on fast SSD C:\ drive, not under any load
  • CPU load <50% max, usually <20%
  • not plotting

Additional context
I have created a Discussion post #4803 , investigated it from "maybe my drives are slow" into this current state "full node is sending bursts of signage points with no apparent reason".

Currently it kind of looks like a malicious attack on network, maybe one or some of my peers or their peers are sending this. Maybe there's something with distinguishing unique messages? (doesn't look like it, since this messages of a burst batch trigger different "plots filter passed", different plots).

Discussion mentioned got exactly zero replies, but now my investigation came far enough to warrant a bug. It looks not right at all, and it also looks like I have no way to influence it, multiple new_signage_point (queries to check my plots) just happen to come in bursts sometimes. I would think it's signage points I've missed, but it's not the case, timings do not match. It's just some extra malicious signage points.

Please investigate and help. Most probably this is happening not just for me.

@dima-stefantsov dima-stefantsov added the bug Something isn't working label May 18, 2021
@azaryc2s
Copy link

azaryc2s commented May 18, 2021

To my understanding this happens on chain forks or if you fell behind in the network for some reasons (unlucky peer-connections or your own network issues). So far i've seen, there is some kind of fix coming for this in the next patch - at least as far as logging goes. If you had proper monitoring, you'd see, that this rarely affects the farmer/harvesters as far as being able to farm for this SPs goes.

@dima-stefantsov
Copy link
Author

As far as I can tell, I never fall behind the chia network, always green "synced", always on latest height, same height my all other ~60 full node peers are at.
I'd say it happens as often as every 30 minutes or so.
I don't see any internet network issues as well, I monitor it constantly (with fping for example) and I never get any losses, always 0% losses.

It does affect my farming, because every burst forces my harvesters to search in plots for every extra signage point, effectively hanging my harvesters for ~30-60 seconds overall (as far as I can interpret logs). That's like 6 missed farm opportunities every time it happens.
Seems like it's increasing my full_node CPU and network usage as well (I can see in logs I'm propagating this bursts to my every peer, I can see CPU usage spikes).
And of course it distracts me from noticing any other real issues my setup might have.

Now that you've mentioned it, I do see 1c808b6 "Fix duplicate signage point spikes" by @mariano54 , thanks for letting me know! If devs can confirm this is exact case that was fixed, then maybe we could close this bug. I'm a bit relieved now, thanks.

@azaryc2s
Copy link

azaryc2s commented May 18, 2021

I also did see those spikes coming in my logs, couldn't find any hard evidence for a specific issue so i just assumed it comes from forked chains -> where you get alot of signage points from the past seconds/minutes where a parallel chain reaches you. At least this is the conclusion i came to, might be wrong tho, so let's hope it gets fixed or at least improved in the next patch :)

Ps. It would be nice to know in the logs for which specific block the signage points are for(logging also the block hash for example)

@n1ghtwish
Copy link

I also see this problem, and like you it causes a metric ton of proofs in a very short space of time, which also locks up new proofs from working properly.

We discussed it in this thread: #1796 (comment)

Anecdotal evidence suggests that the times of the problems are the same for more than just me, which suggests a central issue of some kind. I agree this could be a malicious attack vector.

Not seen a single comment from a developer on preventing this though, it could be worked around by caching all recent signage hashes and not attempting one it's already done, that won't prevent the signage spam, but it would prevent it from actually responding to it.

@dima-stefantsov
Copy link
Author

It is gone with 1.1.6
Thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

3 participants