apache / apache/druid

coordinator restart during index task shutdown may cause succesful task to get failed

Open
#9,912 0 comments 0 reactions 0 assignees View on GitHub
Bug
Dominant language
Java
Stars
14.1k
Forks
3.8k
Avg merge
2d 58m
Merged PRs (30d)
233

Description

### Affected Version
0.17.0

### Description

We got a little unlucky and hit some edge case in the task handling during coordinator restart.

If a task taskes a little too long to shutdown, there is a window during which the task status cannot get queried after it succeeds.

A coordinator/overlord in the process of starting might discover the task in zookeeper and try to query its status. The status call will fail, resulting in the coordinator deciding to kill the task that is about to succeed.

While the task is still in the process of shutting down, the worker will get the signal from the supervisor to kill the task, which closes the input stream on the process, triggering an unclean shutdown with a non-zero exit code of the task. This in turn causes the worker to believe the task failed, despite the task logs showing success.

In our case the chance of hitting the problem was exacerbated by `druid.server.http.unannouncePropagationDelay` being set to 5 seconds, which increased the time between the chathandler no longer being reachable and the process exiting

timeline from logs below

```
coordinator May 20th 2020, 17:54:19.431 Curator-PathChildrenCache-1 INFO Worker[druid-middle-manager-8.druid-middle-manager.druid.svc.cluster.local:8091] wrote RUNNING status for task [index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd] on [TaskLocation{host='druid-middle-manager-8.druid-middle-manager.druid.svc.cluster.local', port=8100, tlsPort=-1}]
coordinator May 20th 2020, 17:54:19.592 LeaderSelector[/druid/prod/overlord/_OVERLORD] INFO Adding task[index_kafka_telemetry_prod_caf1fb5dc7be8a4_bknnbodd] to activeTasks

task 2020-05-20T17:54:21.520Z Task completed with status: {\n \"id\" : \"index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd\",\n \"status\" : \"SUCCESS\",\n \"duration\" : 3840683 [...]
task 2020-05-20T17:54:21.527Z Stopping lifecycle [module] stage [SERVER]
task 2020-05-20T17:54:21.527Z Sleeping 5000 ms for unannouncement to propagate.

coordinator May 20th 2020, 17:54:25.328 IndexTaskClient-mydata-0 WARN Exception while sending request
org.apache.druid.java.util.common.IAE: Received 400 Bad Request with body: {"error":"Can't find chatHandler for handler[index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd]"}
at org.apache.druid.indexing.common.IndexTaskClient.submitRequest(IndexTaskClient.java:356)
at org.apache.druid.indexing.common.IndexTaskClient.submitRequestWithEmptyContent(IndexTaskClient.java:220)
at org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskClient.getStatus(SeekableStreamIndexTaskClient.java:172)
at org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskClient.lambda$getStatusAsync$9(SeekableStreamIndexTaskClient.java:373)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

coordinator May 20th 2020, 17:54:25.767 KafkaSupervisor-mydata INFO Shutdown [index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd] because: [Task [index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd] failed to return status, killing task]

middlemanager May 20th 2020, 17:54:25.769 qtp1008934993-97 INFO Shutdown [index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd] because: [shut down request via HTTP endpoint]
middlemanager May 20th 2020, 17:54:25.769 qtp1008934993-97 INFO Closing output stream to task[index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd].

task 2020-05-20T17:54:25.769Z Triggering JVM shutdown.
task 2020-05-20T17:54:25.770Z Running shutdown hook
task 2020-05-20T17:54:25.770Z Lifecycle [module] already stopped and stop was called. Silently skipping

coordinator May 20th 2020, 17:54:25.778 KafkaSupervisor-mydata INFO Removing task[index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd] from activeTasks
coordinator May 20th 2020, 17:54:25.778 KafkaSupervisor-mydata INFO Sent shutdown message to worker: druid-middle-manager-8.druid-middle-manager.druid.svc.cluster.local:8091, status 200 OK, response: {"task":"index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd"}
coordinator May 20th 2020, 17:54:25.778 KafkaSupervisor-mydata INFO Removing task[index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd] from TaskLock[TimeChunkLock{type=EXCLUSIVE, groupId='index_kafka_mydata', dataSource='mydata', interval=2020-05-20T16:45:00.000Z/2020-05-20T17:00:00.000Z, version='2020-05-20T16:45:00.403Z', priority=75, revoked=false}]

coordinator May 20th 2020, 17:54:25.784 KafkaSupervisor-mydata INFO Removing task[index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd] from TaskLock[TimeChunkLock{type=EXCLUSIVE, groupId='index_kafka_mydata', dataSource='mydata', interval=2020-05-20T17:00:00.000Z/2020-05-20T17:15:00.000Z, version='2020-05-20T17:00:00.331Z', priority=75, revoked=false}]
coordinator May 20th 2020, 17:54:25.790 KafkaSupervisor-mydata INFO Removing task[index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd] from TaskLock[TimeChunkLock{type=EXCLUSIVE, groupId='index_kafka_mydata', dataSource='mydata', interval=2020-05-20T17:15:00.000Z/2020-05-20T17:30:00.000Z, version='2020-05-20T17:15:00.085Z', priority=75, revoked=false}]
coordinator May 20th 2020, 17:54:25.794 KafkaSupervisor-mydata INFO Removing task[index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd] from TaskLock[TimeChunkLock{type=EXCLUSIVE, groupId='index_kafka_mydata', dataSource='mydata', interval=2020-05-20T17:30:00.000Z/2020-05-20T17:45:00.000Z, version='2020-05-20T17:30:00.179Z', priority=75, revoked=false}]
coordinator May 20th 2020, 17:54:25.798 KafkaSupervisor-mydata INFO Removing task[index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd] from TaskLock[TimeChunkLock{type=EXCLUSIVE, groupId='index_kafka_mydata', dataSource='mydata', interval=2020-05-20T17:45:00.000Z/2020-05-20T18:00:00.000Z, version='2020-05-20T17:45:00.319Z', priority=75, revoked=false}]
coordinator May 20th 2020, 17:54:25.805 KafkaSupervisor-mydata INFO Updating task index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd to status: TaskStatus{id=index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd, status=FAILED, duration=-1, errorMsg=null}
coordinator May 20th 2020, 17:54:25.812 KafkaSupervisor-mydata INFO Task done: AbstractTask{id='index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd', groupId='index_kafka_mydata', taskResource=TaskResource{availabilityGroup='index_kafka_mydata_caf1fb5dc7be8a4', requiredCapacity=1}, dataSource='mydata', context={forceTimeChunkLock=true, checkpoints={"0":{"64":47785466457,"16":82873235227}}, IS_INCREMENTAL_HANDOFF_SUPPORTED=true}}
coordinator May 20th 2020, 17:54:25.814 TaskQueue-Manager INFO Shutdown [index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd] because: [task is not in runnerTaskFutures[[index_kafka_mydata_ca0fe6521f5282e_npgglahf, [...] , index_kafka_mydata_3ef307c0ade1ad2_phhakled]]]

middlemanager May 20th 2020, 17:54:25.815 qtp1008934993-110 INFO Closing output stream to task[index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd].
middlemanager May 20th 2020, 17:54:25.815 qtp1008934993-110 INFO Shutdown [index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd] because: [shut down request via HTTP endpoint]

coorindator May 20th 2020, 17:54:25.819 TaskQueue-Manager INFO Sent shutdown message to worker: druid-middle-manager-8.druid-middle-manager.druid.svc.cluster.local:8091, status 200 OK, response: {"task":"index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd"}

middlemanager May 20th 2020, 17:54:26.274 forking-task-runner-0-[index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd] INFO Process exited with status[2] for task: index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd

coordinator May 20th 2020, 17:54:28.133 Curator-PathChildrenCache-1 INFO Worker[druid-middle-manager-8.druid-middle-manager.druid.svc.cluster.local:8091] wrote FAILED status for task [index_kafka_mydata_caf1fb5dc7be8a4_bknnbodd] on [TaskLocation{host='druid-middle-manager-8.druid-middle-manager.druid.svc.cluster.local', port=8100, tlsPort=-1}]
```

Contributor guide

Open the contributing guide

Research direction

Start with SeekableStreamIndexTaskClient.getStatus and the KafkaSupervisor shutdown and task-status handling described in the logs. Trace coordinator restart behavior when a task has completed but its status endpoint is temporarily unavailable; done means a successfully completed task is not marked FAILED or killed during that window, with regression coverage for the timing case.

Written by the indexing model from the issue text.

Assessment

Tech stack
java
Domain
backend, distributed-systems
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.