Index Kafka job throws Interrupted Exception during shutdown.

[ruibinx]

Affected Version

0.19.0

Description

Occasionally index kafka job throw interrupted exception during shutdown. All the ingested segments are unannounced though the ingestion phase is complete.

Besides the exception is not showed in report `errorMsg', I'm not sure if it's intended.

{
  "id": "index_kafka_metric_duration_result_acb68b573f08e0e_jjfpjpnj",
  "groupId": "index_kafka_metric_duration_result",
  "type": "index_kafka",
  "createdTime": "2021-02-19T00:13:39.461Z",
  "queueInsertionTime": "1970-01-01T00:00:00.000Z",
  "statusCode": "FAILED",
  "status": "FAILED",
  "runnerStatusCode": "WAITING",
  "duration": -1,
  "location": {
    "host": "dx-pipe-pt25-pm",
    "port": 8109,
    "tlsPort": -1
  },
  "dataSource": "metric_duration_result",
  "errorMsg": null
}

related logs:

2021-02-19T00:51:53,911 INFO [Thread-43] org.apache.druid.curator.announcement.Announcer - Unannouncing [/druid/segments/dx-pipe-pt25-pm:8109/dx-pipe-pt25-pm:8109_indexer-executor__default_tier_2021-02-19T00:42:53.161Z_dc01fd4a65cc4376935d93738792c68b2]
2021-02-19T00:51:53,919 INFO [Thread-43] org.apache.druid.curator.announcement.Announcer - Unannouncing [/druid/internal-discovery/PEON/dx-pipe-pt25-pm:8109]
2021-02-19T00:51:53,931 INFO [Thread-43] org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle [module] stage [SERVER]
2021-02-19T00:51:53,936 INFO [Thread-43] org.eclipse.jetty.server.AbstractConnector - Stopped ServerConnector@37364634{HTTP/1.1,[http/1.1]}{0.0.0.0:8109}
2021-02-19T00:51:53,936 INFO [Thread-43] org.eclipse.jetty.server.session - node0 Stopped scavenging
2021-02-19T00:51:53,938 INFO [Thread-43] org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@7544260a{/,null,UNAVAILABLE}
2021-02-19T00:51:53,940 INFO [Thread-43] org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle [module] stage [NORMAL]
2021-02-19T00:51:53,941 INFO [Thread-43] org.apache.druid.server.coordination.ZkCoordinator - Stopping ZkCoordinator for [DruidServerMetadata{name='dx-pipe-pt25-pm:8109', hostAndPort='dx-pipe-pt25-pm:8109', hostAndTlsPort='null', maxSize=0, tier='_default_tier', type=indexer-executor, priority=0}]
2021-02-19T00:51:53,941 INFO [Thread-43] org.apache.druid.server.coordination.SegmentLoadDropHandler - Stopping...
2021-02-19T00:51:53,941 INFO [Thread-43] org.apache.druid.server.coordination.SegmentLoadDropHandler - Stopped.
2021-02-19T00:51:53,941 INFO [Thread-43] org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner - Starting graceful shutdown of task[index_kafka_metric_duration_result_acb68b573f08e0e_jjfpjpnj].
2021-02-19T00:51:53,942 INFO [Thread-43] org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner - Stopping forcefully (status: [READING])
2021-02-19T00:51:53,944 INFO [LookupExtractorFactoryContainerProvider-MainThread] org.apache.druid.query.lookup.LookupReferencesManager - Lookup Management loop exited. Lookup notices are not handled anymore.
2021-02-19T00:51:53,944 INFO [Thread-43] org.apache.druid.query.lookup.LookupReferencesManager - Closed lookup [productId2Platform].
2021-02-19T00:51:53,943 ERROR [task-runner-0-priority-0] org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner - Encountered exception in run() before persisting.
java.lang.RuntimeException: java.lang.InterruptedException
	at org.apache.druid.indexing.common.actions.RemoteTaskActionClient.submit(RemoteTaskActionClient.java:125) ~[druid-indexing-service-0.19.0.jar:0.19.0]
	at org.apache.druid.indexing.appenderator.ActionBasedSegmentAllocator.allocate(ActionBasedSegmentAllocator.java:57) ~[druid-indexing-service-0.19.0.jar:0.19.0]
	at org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver.getSegment(BaseAppenderatorDriver.java:334) ~[druid-server-0.19.0.jar:0.19.0]
	at org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver.append(BaseAppenderatorDriver.java:402) ~[druid-server-0.19.0.jar:0.19.0]
	at org.apache.druid.segment.realtime.appenderator.StreamAppenderatorDriver.add(StreamAppenderatorDriver.java:187) ~[druid-server-0.19.0.jar:0.19.0]
	at org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner.runInternal(SeekableStreamIndexTaskRunner.java:653) [druid-indexing-service-0.19.0.jar:0.19.0]
	at org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner.run(SeekableStreamIndexTaskRunner.java:277) [druid-indexing-service-0.19.0.jar:0.19.0]
	at org.apache.druid.indexing.seekablestream.SeekableStreamIndexTask.run(SeekableStreamIndexTask.java:164) [druid-indexing-service-0.19.0.jar:0.19.0]
	at org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner$SingleTaskBackgroundRunnerCallable.call(SingleTaskBackgroundRunner.java:421) [druid-indexing-service-0.19.0.jar:0.19.0]
	at org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner$SingleTaskBackgroundRunnerCallable.call(SingleTaskBackgroundRunner.java:393) [druid-indexing-service-0.19.0.jar:0.19.0]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_171]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_171]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_171]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_171]
Caused by: java.lang.InterruptedException
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:998) ~[?:1.8.0_171]
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304) ~[?:1.8.0_171]
	at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:285) ~[guava-16.0.1.jar:?]
	at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116) ~[guava-16.0.1.jar:?]
	at org.apache.druid.discovery.DruidLeaderClient.go(DruidLeaderClient.java:173) ~[druid-server-0.19.0.jar:0.19.0]
	at org.apache.druid.discovery.DruidLeaderClient.go(DruidLeaderClient.java:145) ~[druid-server-0.19.0.jar:0.19.0]
	at org.apache.druid.indexing.common.actions.RemoteTaskActionClient.submit(RemoteTaskActionClient.java:82) ~[druid-indexing-service-0.19.0.jar:0.19.0]
	... 13 more
2021-02-19T00:51:53,957 INFO [HttpClient-Netty-Worker-21] org.apache.druid.java.util.http.client.pool.ResourcePool - giveBack called after being closed. key[http://dx-pipe-sata458-pm:8090]
2021-02-19T00:51:53,957 WARN [HttpClient-Netty-Worker-21] org.apache.druid.java.util.http.client.NettyHttpClient - [POST http://dx-pipe-sata458-pm:8090/druid/indexer/v1/action] Channel disconnected before response complete
2021-02-19T00:51:53,959 INFO [[index_kafka_metric_duration_result_acb68b573f08e0e_jjfpjpnj]-appenderator-persist] org.apache.druid.segment.realtime.appenderator.AppenderatorImpl - Flushed in-memory data for segment[metric_duration_result_2021-02-14T21:00:00.000Z_2021-02-14T22:00:00.000Z_2021-02-18T02:48:34.278Z_223] spill[1] to disk in [11] ms (16 rows).
2021-02-19T00:51:53,959 INFO [task-runner-0-priority-0] org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Unannouncing segment[metric_duration_result_2021-02-17T08:00:00.000Z_2021-02-17T09:00:00.000Z_2021-02-18T02:39:13.565Z_890] at path[/druid/segments/dx-pipe-pt25-pm:8109/dx-pipe-pt25-pm:8109_indexer-executor__default_tier_2021-02-19T00:13:54.322Z_b62ef49624db40619bdf522d5b96e9f70]
2021-02-19T00:51:53,960 INFO [task-runner-0-priority-0] org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Unannouncing segment[metric_duration_result_2021-02-17T11:00:00.000Z_2021-02-17T12:00:00.000Z_2021-02-18T02:39:12.940Z_937] at path[/druid/segments/dx-pipe-pt25-pm:8109/dx-pipe-pt25-pm:8109_indexer-executor__default_tier_2021-02-19T00:13:54.322Z_b62ef49624db40619bdf522d5b96e9f70]
2021-02-19T00:51:53,960 INFO [task-runner-0-priority-0] org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Unannouncing segment[metric_duration_result_2021-02-12T19:00:00.000Z_2021-02-12T20:00:00.000Z_2021-02-18T02:48:12.626Z_616] at path[/druid/segments/dx-pipe-pt25-pm:8109/dx-pipe-pt25-pm:8109_indexer-executor__default_tier_2021-02-19T00:42:53.161Z_dc01fd4a65cc4376935d93738792c68b2]

[zhangyouxun]

I met the same problem.how to solve it？

[jasonk000]

Seems most likely related to this

druid/indexing-service/src/main/java/org/apache/druid/indexing/seekablestream/SeekableStreamIndexTask.java

Lines 155 to 163 in 8296123

	@Override
	public void stopGracefully(TaskConfig taskConfig)
	{
	if (taskConfig.isRestoreTasksOnRestart()) {
	getRunner().stopGracefully();
	} else {
	getRunner().stopForcefully();
	}
	}

If druid.indexer.task.restoreTasksOnRestart is not true, then stopForcefully is issued.

[github-actions]

This issue has been marked as stale due to 280 days of inactivity.
It will be closed in 4 weeks if no further activity occurs. If this issue is still
relevant, please simply write any comment. Even if closed, you can still revive the
issue at any time or discuss it on the dev@druid.apache.org list.
Thank you for your contributions.

[github-actions]

This issue has been closed due to lack of activity. If you think that
is incorrect, or the issue requires additional review, you can revive the issue at
any time.