zebrad silently stalls if peers close the connection

[teor2345]

If all our peers close their connections, zebrad will silently stall, without logging any further information.

Instead, we should regularly log a peer status, increasing its log level based on the time since a new peer.

It looks like zebra-network has some timeout logic, but I can't see any logs after several minutes. I don't know if it works at the version stage of the connection. (Or if it is meant to log anything.)

[dconnolly]

I think this may be the behavior I've seen when running zebrad on our node deployments _sometimes_, just stalling out, not crashing, not logging anything else on [info], etc

[teor2345]

It should be happening consistently right now, because our network protocol version is rejected by zcashd after Heartwood.

I wonder if Heartwood disconnections have affected the Zebra DNS seeders as well. Can you or @gtank check?

[teor2345]

The fix for the heartwood issue is in PR #702.

[hdevalence]

Hmm, increasing the log level doesn't seem right to me. In our current model, the span and event levels are fixed properties of spans and events, which allows us to do dynamic filtering, zooming in to particular parts of the program and execution context using the tracing endpoint. Here the consumer of the tracing output has full control over what information to filter for. However, if we have a component that does its own dynamic filtering through a different mechanism, then we have two places where de facto filters are set, but one (adjusting levels) interferes with the second one (filtering).

Basically, the point here is that it seems like wanting to regularly log a peer status is a problem about not having good observability for Zebra's internals, and rather than having a one-off fix for this specific case, we should try to improve our generic observability systems (tracing / metrics), which have a payoff across the whole codebase.

[teor2345]

I agree about the peer set, but I also wonder if we're talking about slightly different things here.

If zebra stalls, I eventually want to see an warning or error explaining why. But doesn't need to come from any particular component or part of the code.

[hdevalence]

I think a good way to handle this would be to add a warning message in the peer set's poll_ready implementation, warning if poll_ready is called when we have no peers (not just no ready peers, but no peers at all). Because poll_ready is called before making network requests, this means that if zebra stalls from losing all peers, we'll get a message logged whenever something tries to access the network (which happens periodically from the syncer).

This might also cause a warning when we're starting up, but I don't think that that's a big problem.

[teor2345]

There might even be a way to distinguish startup from a peer set that was populated, but has become empty.
(It would be nice to avoid a spurious warning, because it will confuse users, and perhaps result in bug reports.)

Let's see what we can do.

[hdevalence]

Sure, we could store a had_peers: bool initialized to false and set it to true as soon as we get the first peer. Then we warn only if ... && self.had_peers { ... }.