stacks-node loses outbound peers when broadcasting events

[CharlieC3]

The stacks-node is susceptible to losing all outbound peers when broadcasting events to a stacks-blockchain-api, causing it to fall behind the chain tip potentially for hours until the stacks-node is restarted.
During this time, the stacks-node printing plenty of PermanentlyDrained logs like such:
http:id=234,request=false,peer=<redacted>: failed to recv: PermanentlyDrained

Expected behavior
If a stacks-node loses all outbound peers, it should be able to acquire new ones or re-validate old ones relatively quickly.

Debug Information
If this happens again, I'll get more debug information like:

• running 'select * from frontier;' in the peers.db before/after restarting the stacks-node.
• checking open network connections before/after restarting the stacks-node

stacks-node version: 2.05.0.2.0

[wileyj]

one more thing to check is the DB load/queries when this happens

[jcnelson]

I'd also look at things originating from src/net/neighbors.rs on the INFO, WARN, or ERRO level.

[CharlieC3]

@wileyj According to our DB metrics, it was under normal load during the day which the stacks-node lost all outbound peers.

@jcnelson No ERRO level logs at all. However, I do see some of these logs around the time all outbound peers were lost (~1433 UTC):
local.1://(bind=0.0.0.0:20444)(pub=None): Failed to begin neighbor walk from pingback: NoSuchNeighbor

Here's some logs filtered to src/net/neighbors.rs between 1400 - 1500 UTC. The issue occurs around 1433 UTC:
src-net-neighbors-3145.csv

[wileyj]

@wileyj According to our DB metrics, it was under normal load during the day which the stacks-node lost all outbound peers.

@jcnelson No ERRO level logs at all. However, I do see some of these logs around the time all outbound peers were lost (~1433 UTC): local.1://(bind=0.0.0.0:20444)(pub=None): Failed to begin neighbor walk from pingback: NoSuchNeighbor

Here's some logs filtered to src/net/neighbors.rs between 1400 - 1500 UTC. The issue occurs around 1433 UTC: src-net-neighbors-3145.csv

one more thing you could look at if you have the data - slow query log, to see if there were any slow queries around the time you noticed the issue. doesn't seem like the API DB is the problem though

[CharlieC3]

All I can find is a small blip where there was a slow query which took about 9 seconds to return around 1429 UTC on May 21st, but infrequent slow queries like those are not unheard of.
Depending on the query complexity, queries over 5 seconds could occur dozens of times a day.

Cross-comparing it to today's metrics, these queries don't appear to have any effect on the outbound peers for the live stacks-node broadcasting events.

[CharlieC3]

@deantchi and I found something pretty interesting. It seems the stacks-node we're running which broadcasts to the API wasn't the only node in our infrastructure to have lost all outbound peers.

From the screenshot, it's clear 3 other nodes lost all outbound peers. The difference is that the other 3 nodes were able to recover in about 5 minutes, while the stacks-node broadcasting events didn't recover for a few hours until it was restarted.

This screenshot is the same three nodes, but over a longer time period. You can see the stacks-node broadcasting events would get an outbound peer or two every so often, but would lose it pretty quickly.
This may explain why I noticed the API was still receiving mempool TXs periodically.

[jcnelson]

Thanks for the csv. Can you make me one that also includes src/net/chat.rs and src/net/p2p.rs, in addition to src/net/neighbors.rs?

Also, to be sure -- you're using a different node private key on each node, right? You can check via /v2/info and looking at node_public_key -- it should be different for each node.

[CharlieC3]

Here are the other log files. The src/net/p2p.rs log is quite long, so I had to trim the timeline down to 1420 - 1500 UTC.
src-net-p2p-3145.csv
src-net-chat-3145.csv

You're using a different node private key on each node, right?

These are just followers, not miners. Does the seed property need to be configured for each of them regardless?

[jcnelson]

I'm seeing lots of HandshakeRejects in /src/net/chat.rs, which indicates that your node is doing something wrong. Unfortunately we can't see the reason since that's logged on the remote node doing the rejection. But, the possible reasons are as follows:

• You're using the same local_peer_seed as the remote node, which will make the remote node think it's trying to handshake to itself (since it has the same signature as its own private key)

• The handshake's reported public key expiry block has passed (this is unlikely)

• Your node is an outbound peer of the remote node (i.e. the remote node reaches out to yours first), and the IP address your node reports is different than the one that the remote node used to contact you

[CharlieC3]

@jcnelson One of our stacks-nodes broadcasting events lost all outbound peers again this weekend, and was unable to reliably hold on to more than 1 peer after this happened. Before restarting the node, I was able to get a dump of the frontier table in the peers DB, and print some connection info too. I recollected the info again shortly after the reboot.

connections_after.txt
connections_before.txt
frontier_after.txt
frontier_before.txt

This week I'm testing setting the local_peer_seed config in each stacks-node broadcasting events with a unique hex string to see if there's any noticeable effect on the outbound peers. We might end up needing more than 1 week to be sure of any results, since this problem doesn't occur every week, but I'm thinking we may still be able to learn something.

cc @wileyj

[CharlieC3]

You're using the same local_peer_seed as the remote node, which will make the remote node think it's trying to handshake to itself (since it has the same signature as its own private key)

If the local_peer_seed property is not defined in the config.toml, doesn't the binary generate a random hex string to use at bootup? Unless I'm misunderstanding something, it should be near impossible for two nodes to generate the same local_peer_seed value, right?

Your node is an outbound peer of the remote node (i.e. the remote node reaches out to yours first), and the IP address your node reports is different than the one that the remote node used to contact you

None of the nodes losing outbound peers are exposed publicly, so I don't see how they could be considered an outbound peer of an external node. They could likely only be outbound peers of other nodes within the same private network.

[CharlieC3]

Jude answered my question above in the weekly blockchain meeting. Posting answer for posterity.

If the local_peer_seed property is not defined in the config.toml, doesn't the binary generate a random hex string to use at bootup? Unless I'm misunderstanding something, it should be near impossible for two nodes to generate the same local_peer_seed value, right?

The stacks-node will generate a local_peer_seed at bootup if started with an empty working directory. However since we boot our stacks-nodes with a snapshot, they all start with essentially the same working directory, and thus have the same local_peer_seed value, which may have been causing issues.

---

@jcnelson One of our stacks-nodes broadcasting events lost all outbound peers again last night for almost 4 hours until it was restarted. This stacks-node is running with a unique local_peer_seed configured, so it seems changing this property does not have a large enough effect to mitigate this problem.

Please let me know if there's any additional data I can help provide which would help in the investigation of this problem.

[jcnelson]

This stacks-node is running with a unique local_peer_seed configured

Is this also the case in the peers DB? i.e. the local_peer table reflects the unique peer seed?

[CharlieC3]

@jcnelson Hmm, unexpectedly, the entry in the local_peer table does not appear to be unique despite local_peer_seed being set to a unique 32 character hex string. I'm guessing updating this entry could do the trick, but it doesn't seem to be doing so at bootup. Is this a bug?

[jcnelson]

Yeah, the node really should override the private key in local_peer with whatever is in local_peer_seed if explicitly set. Wanna open a separate issue for that?

If you fix the local_peer table, does the problem go away?