Distinguish between unresponsive node and unreachable node

[Leaf-Lin]

Today, Elasticsearch log emit very similar messages around unresponsive node and unreachable node.

As an end-user, it is not easy to tell whether the problem lies in the network (platform) layer when the destination is completely unreachable or in Elasticsearch when it was overwhelmed with requests and becomes slow to respond.

Some of the relevant logs look like:

[2021-05-07T15:02:28,704][ERROR][o.e.x.m.c.c.ClusterStatsCollector] [elastic-05] collector [cluster_stats] timed out when collecting data
[2021-05-07T15:02:57,757][ERROR][o.e.x.m.c.e.EnrichStatsCollector] [elastic-05] collector [enrich_coordinator_stats] timed out when collecting data
[2021-05-07T15:03:07,786][ERROR][o.e.x.m.c.i.IndexRecoveryCollector] [elastic-05] collector [index_recovery] timed out when collecting data
[2021-05-07T15:03:17,801][ERROR][o.e.x.m.c.i.IndexStatsCollector] [elastic-05] collector [index-stats] timed out when collecting data
[2021-05-07T15:16:43,101][WARN ][o.e.c.c.Coordinator      ] [elastic-05] failed to validate incoming join request from node [{elastic-04}{uaH7bAt2TgaLhcKCkxpu6Q}{r3IPD7o4SXarFHKmjlNy0Q}{xx.xx.xx.xx}{10.10.10.5:9300}{dim}{xpack.installed=true}] org.elasticsearch.transport.NodeDisconnectedException: [elastic-04][10.10.10.5:9300][internal:cluster/coordination/join/validate] disconnected
[2021-05-07T15:18:12,085][INFO ][o.e.c.c.C.CoordinatorPublication] [elastic-05] after [10s] publication of cluster state version [536546] is still waiting for {elastic-04}{uaH7bAt2TgaLhcKCkxpu6Q}{r3IPD7o4SXarFHKmjlNy0Q}{xx.xx.xx.xx}{10.10.10.5:9300}{dim}{xpack.installed=true} [SENT_APPLY_COMMIT]
[2021-05-07T15:18:28,006][WARN ][o.e.c.r.a.AllocationService] [elastic-05] failing shard [failed shard, shard [index_v1][0], node[uaH7bAt2TgaLhcKCkxpu6Q], [P], recovery_source[existing store recovery; bootstrap_history_uuid=false], s[INITIALIZING], a[id=eOGoLSllTG6UfYJPYg6cNg], unassigned_info[[reason=ALLOCATION_FAILED], at[2021-05-07T05:18:12.222Z], failed_attempts[4], failed_nodes[[uaH7bAt2TgaLhcKCkxpu6Q]], delayed=false, details[failed shard on node [uaH7bAt2TgaLhcKCkxpu6Q]: failed to create shard, failure IOException[failed to obtain in-memory shard lock]; nested: ShardLockObtainFailedException[[index_v1][0]: obtaining shard lock timed out after 5000ms, previous lock details: [shard creation] trying to lock for [shard creation]]; ], allocation_status[no_valid_shard_copy]], message [failed to create shard], failure [IOException[failed to obtain in-memory shard lock]; nested: ShardLockObtainFailedException[[index_v1][0]: obtaining shard lock timed out after 5000ms, previous lock details: [shard creation] trying to lock for [shard creation]]; ], markAsStale [true]]
[2021-05-07T15:49:33,607][INFO ][o.e.c.s.MasterService    ] [elastic-05] node-left[{elastic-02}{4aWwRxagRAyG_WkUHhV2qg}{moK_JcYnS1efIYWdNrlBkA}{xx.xx.xx.xx}{10.10.10.11:9300}{xpack.installed=true} reason: disconnected], term: 219, version: 538374, delta: removed {{elastic-02}{4aWwRxagRAyG_WkUHhV2qg}{moK_JcYnS1efIYWdNrlBkA}{xx.xx.xx.xx}{10.10.10.11:9300}{xpack.installed=true}}
[2021-05-07T15:49:33,661][INFO ][o.e.c.s.ClusterApplierService] [elastic-05] removed {{elastic-02}{4aWwRxagRAyG_WkUHhV2qg}{moK_JcYnS1efIYWdNrlBkA}{xx.xx.xx.xx}{10.10.10.11:9300}{xpack.installed=true}}, term: 219, version: 538374, reason: Publication{term=219, version=538374}
[2021-05-07T15:50:41,662][INFO ][o.e.c.s.MasterService    ] [elastic-05] node-join[{elastic-02}{4aWwRxagRAyG_WkUHhV2qg}{l2U2E0UbR96U_8ykelwcDw}{xx.xx.xx.xx}{10.10.10.11:9300}{xpack.installed=true} join existing leader], term: 219, version: 538375, delta: added {{elastic-02}{4aWwRxagRAyG_WkUHhV2qg}{l2U2E0UbR96U_8ykelwcDw}{xx.xx.xx.xx}{10.10.10.11:9300}{xpack.installed=true}}
[2021-05-07T15:50:42,445][INFO ][o.e.c.s.ClusterApplierService] [elastic-05] added {{elastic-02}{4aWwRxagRAyG_WkUHhV2qg}{l2U2E0UbR96U_8ykelwcDw}{xx.xx.xx.xx}{10.10.10.11:9300}{xpack.installed=true}}, term: 219, version: 538375, reason: Publication{term=219, version=538375}

It would be great if Elasticsearch can intercept early and stop running some of these checkup services just reporting the node is unreachable via ping and retry later.

[elasticmachine]

Pinging @elastic/es-distributed (Team:Distributed)

[DaveCTurner]

It would be great if Elasticsearch can intercept early and stop running some of these checkup services just reporting the node is unreachable via ping and retry later.

We already do this, although of course we can only determine "unreachable" by observing a timeout too and the timeouts on the stats collection services are shorter than the timeout for reachability since removing a node from the cluster is a much bigger deal than some missing stats.

Improving logging and other diagnostic outputs to help with this kind of thing are an ongoing project. Although it's true that the messages are superficially quite similar, there are some important differences in many cases that point one way or another. For instance, network disconnections should only occur after a node-left message is logged, so if you see a NodeDisconnectedException first (or a node-left ... reason: disconnected) then the initial trigger was almost certainly network-related.

In practice there's only so far we can ourselves go along the diagnostic path within an unprivileged userspace process like Elasticsearch. A node cannot determine whether a remote peer is unresponsive or just unreachable because in either case all we see are timeouts. The crucial diagnostic question here is whether something other than Elasticsearch can form network connections, which of course we cannot use Elasticsearch itself to answer. We cannot see the details of the packets on the wire, without which it's often impossible to pinpoint the problem.

A node cannot reliably determine that it is itself unresponsive either, since if it were then the service for checking its responsiveness would also be unresponsive. We do already report on many cases where it looks like we froze for a while (e.g. on a long GC, or if the clock jumps too far). We might also be unresponsive due to a bug. We'd rather address that by fixing the bug rather than by handling the unresponsiveness more gracefully, but we do also log messages in many cases where it looks like we might have encountered a bug like that. We've addressed some such bugs in recent versions.

Not really sure what to do with this issue. I agree it's a good idea in principle, but we'll never reach perfection, so maybe a Github issue tracking progress towards the goal isn't the right thing.

---

Edit to add: another obstacle to doing these diagnostics within Elasticsearch itself is that in many cases we need to correlate evidence from across the whole cluster to work out what's going on, which isn't feasible if nodes aren't responding or connectivity is disrupted.

[DaveCTurner]

We (@elastic/es-distributed) discussed this as a team today. We recognised the problems raised here but feel the situation is vastly improved in recent versions. We'll leave this open for further comments until the release of 7.14 and then look back over cases involving versions ≥7.12 to determine how much room for further improvement we can see.