The stacktrace made more understandishable:

org.jboss.netty.channel.ChannelException: Faulty channel in resource pool
  at org.apache.druid.java.util.http.client.NettyHttpClient.go(NettyHttpClient.java:131)
  at org.apache.druid.server.coordination.ChangeRequestHttpSyncer.sync(ChangeRequestHttpSyncer.java:218)
  at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
  at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
  at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
  at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
  at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
  at java.base/java.lang.Thread.run(Thread.java:829)
  Caused by: org.jboss.netty.channel.ConnectTimeoutException: connection timed out: /10.4.132.249:8091
  at org.jboss.netty.channel.socket.nio.NioClientBoss.processConnectTimeout(NioClientBoss.java:139)
  at org.jboss.netty.channel.socket.nio.NioClientBoss.process(NioClientBoss.java:83)
  at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)
  at org.jboss.netty.channel.socket.nio.NioClientBoss.run(NioClientBoss.java:42)
  at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
  at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
  ... 3 more\n

This leads me to believe that the coordinator is still attempting to communicate with the indexer.

I am curious if anyone else has seen an error like this.

It appears that once it gets into this state it will continue to retry indefinitely, and eventually the coordinator becomes bogged down and non-responsive

If the coordinator pod is deleted it whoever takes over as leader is usually fine, but eventually this occurs again

I would like to be able to specify the retry limit for errors such as these so that they don't build up over time and destabilize the coordinator.

I'm wondering if, at the time this was logged, did 10.4.132.249 exist?

Could be a stale caching thing?

That would be consistent with the behavior you mentioned: restarting fixes it, but it gets back into the state over time

I do have these errors when I use

http

for server inventory. We switched them back to

batch

and never got those errors.

• Is the Indexer in a statefulset? i.e getting the same hostname when it returns with a different IP?

We run everything as deployments, so each pod gets a new IP.

there have been other conversations where the host resolution caching in the JVM is the culprit, but I'm not sure if this is at play here.

This was one of my first ideas, that the JVM was using a stale IP. I expected that there would be a limit on the number of retries before the coordinator flags the node as out of service and removes it from memory.

This does sound like a service discovery issue

Like, something related to K8sDruidNodeDiscoveryProvider

I am not a k8s expert so I am not sure exactly how that class is supposed to work

But I am guessing it is returning some quite stale IPs in some cases

(For reference, the ZK-based version works through ephemeral znode watches: when a server goes away, it stops heartbeating with ZK, so its ephemeral znode is deleted. The CuratorDruidNodeDiscoveryProvider notices that and removes the server from the active list.)

Thanks Cory, that would be awesome For reference: the way things are supposed to work is the DruidNodeDiscovery (from the K8sDruidNodeDiscoveryProvider, or any other discovery provider) is the final word on what the correct list of servers is for a given role. So the expectation in this case is once a server goes offline, the discovery impl will notice it somehow, and update its list. Then clients will stop trying to talk to it

I found an NPE right after that

java.lang.NullPointerException
at org.apache.druid.client.HttpServerInventoryView$2.toDruidServer(HttpServerInventoryView.java:179)
at org.apache.druid.client.HttpServerInventoryView$2.lambda$nodesRemoved$1(HttpServerInventoryView.java:161)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)\n\tat java.base/java.util.Collections$UnmodifiableCollection.forEach(Collections.java:1085)
at org.apache.druid.client.HttpServerInventoryView$2.nodesRemoved(HttpServerInventoryView.java:161)

It appears that either

node.getServices()

or

((DataNodeService) node.getServices().get(DataNodeService.DISCOVERY_SERVICE_KEY))

is returning null.

I'm going to see if I can trap this in the debugger and look at the state of the

HttpServerInventoryView

when this occurs.

The NPE is getting caught and produce the error message here https://github.com/apache/druid/blob/0.23.0/server/src/main/java/org/apache/druid/discovery/DruidNodeDiscoveryProvider.java#L211

Although is prints an error log, it ignores the actual error.

I am guess this is because the error is non-fatal.

I snagged a screenshot of the node as it is being removed. Indeed, there are no services listed.

Okay, I think I know what is happening. As a result of the NPE, the node is not actually removed from the service list. I think the fix is to put null-safe access on the calls to

((DataNodeService) node.getServices().get(DataNodeService.DISCOVERY_SERVICE_KEY))

at https://github.com/apache/druid/blob/0.23.0/server/src/main/java/org/apache/druid/client/HttpServerInventoryView.java#L175-L182

I wonder how the peon

DruidNode

got created without any

services

, that is likely the source of this

I have traced this back to when the peon announcement is received. It doesn't have any services defined on it.

The indexer-executor announcements contain services but not the peons

According to the source these nodes without services are never stored into the in-memory map https://github.com/apache/druid/blob/0.23.0/server/src/main/java/org/apache/druid/discovery/DruidNodeDiscoveryProvider.java#L154-L167

Ok, so from what I can see in the debugger there's no actual bug here. Peon announcements are ignored, and peon un-announcements are also ignored (albeit through an error log can ignore exception). I now need to determine why the coordinator is attempting to sync with the node.

That seems to indicate that a

ChangeRequestHttpSyncer

is still running for a segment after the pod hosting that segment has gone away. I wonder if this is related to segment announcements, not service announcements.

the Coordinator does use those to maintain its view of which servers have which segments (so it can manage balancing & replication)

It's bootstrapped from a DruidNodeDiscoveryProvider, which I originally guessed was the problem

It is also possible that the DruidNodeDiscoveryProvider is OK and the issue is that the HttpServerInventoryView doesn't follow changes properly

what is the nslookup on old IP (10.4.132.249) gives

Picking this investigation up; I have noticed that when a node shuts down and un-announces itself I consistently see a K8s error:

{
  "level": "WARN",
  "@timestamp": "2022-09-30T19:39:49.121Z",
  "thread": "Thread-49",
  "message": "Retrying (2 of 2) in 2,504ms.",
  "exception": {
    "exception_class": "<http://org.apache.druid.java.util.common.RE|org.apache.druid.java.util.common.RE>",
    "exception_message": "Failed to patch pod[cj/storage--druid-coordinator-5bfc57477-vqlqs], code[422], error[{\n  \"kind\": \"Status\",\n  \"apiVersion\": \"v1\",\n  \"metadata\": {\n    \n  },\n  \"status\": \"Failure\",\n  \"message\": \"the server rejected our request due to an error in our request\",\n  \"reason\": \"Invalid\",\n  \"details\": {\n    \n  },\n  \"code\": 422\n}].",
    "stacktrace": "<http://org.apache.druid.java.util.common.RE|org.apache.druid.java.util.common.RE>: Failed to patch pod[cj/storage--druid-coordinator-5bfc57477-vqlqs], code[422], error[{\n  \"kind\": \"Status\",\n  \"apiVersion\": \"v1\",\n  \"metadata\": {\n    \n  },\n  \"status\": \"Failure\",\n  \"message\": \"the server rejected our request due to an error in our request\",\n  \"reason\": \"Invalid\",\n  \"details\": {\n    \n  },\n  \"code\": 422\n}].\n\tat org.apache.druid.k8s.discovery.DefaultK8sApiClient.patchPod(DefaultK8sApiClient.java:71)\n\tat org.apache.druid.k8s.discovery.K8sDruidNodeAnnouncer.lambda$unannounce$2(K8sDruidNodeAnnouncer.java:148)\n\tat org.apache.druid.java.util.common.RetryUtils.retry(RetryUtils.java:129)\n\tat org.apache.druid.java.util.common.RetryUtils.retry(RetryUtils.java:81)\n\tat org.apache.druid.java.util.common.RetryUtils.retry(RetryUtils.java:163)\n\tat org.apache.druid.java.util.common.RetryUtils.retry(RetryUtils.java:153)\n\tat org.apache.druid.k8s.discovery.K8sDruidNodeAnnouncer.unannounce(K8sDruidNodeAnnouncer.java:146)\n\tat org.apache.druid.cli.ServerRunnable$DiscoverySideEffectsProvider$1.stop(ServerRunnable.java:191)\n\tat org.apache.druid.java.util.common.lifecycle.Lifecycle.stop(Lifecycle.java:368)\n\tat org.apache.druid.java.util.common.lifecycle.Lifecycle$1.run(Lifecycle.java:401)\n\tat java.base/java.lang.Thread.run(Thread.java:829)\nCaused by: io.kubernetes.client.openapi.ApiException: Unprocessable Entity\n\tat io.kubernetes.client.openapi.ApiClient.handleResponse(ApiClient.java:993)\n\tat io.kubernetes.client.openapi.ApiClient.execute(ApiClient.java:905)\n\tat io.kubernetes.client.openapi.apis.CoreV1Api.patchNamespacedPodWithHttpInfo(CoreV1Api.java:41306)\n\tat io.kubernetes.client.openapi.apis.CoreV1Api.patchNamespacedPod(CoreV1Api.java:41261)\n\tat org.apache.druid.k8s.discovery.DefaultK8sApiClient.patchPod(DefaultK8sApiClient.java:68)\n\t... 10 more\n"
  },
  "hostName": "storage--druid-coordinator-5bfc57477-vqlqs"
}

I looked at the k8s extension, it it is using kubenetes client jar version

11.0.1

, but the latest is

16.0.0

I'm attempting to update the k8s client jar and fix any breaking changes to see if I can resolve this.

at any rate, i think it makes sense if the official druid extension is built against the latest k8s

I believe I am ready to begin the PR process!!!

@Gian Merlino consider this me officially volunteering to adopt the kubernetes extension as the maintainer. We will be continuing to operate it inside our production clusters and perform upstream maintenance and expansion.

i made some notes on the patch