pchang388 commented on issue #12701:
URL: https://github.com/apache/druid/issues/12701#issuecomment-1183609910
Hi all,
So we upgraded to 0.23.0 and the problem still persists unfortunately. We
have 50% or more of the tasks fail at times with the same/similar error,
example:
1. Task: `index_kafka_REDACT_e628ac753b0f515_mifoboff`, start time:
`2022-07-13T18:05:22,087`, was in `READING` state
* Some logs from Overlord
```
2022-07-13T19:05:09,790 INFO [IndexTaskClient-REDACT-1]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskClient - Task
[index_kafka_REDACT_e628ac753b0f515_mifoboff] paused successfully
2022-07-13T19:05:12,435 INFO [KafkaSupervisor-REDACT]
org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor -
{id='REDACT', generationTime=2022-07-13T19:05:12.435Z,
payload=KafkaSupervisorReportPayload{dataSource='REDACT', topic='REDACT',
partitions=6, replicas=1, durationSeconds=3600,
active=[{id='index_kafka_REDACT_b803d3572726dca_joklmebc',
startTime=2022-07-13T19:05:03.970Z, remainingSeconds=3591},
{id='index_kafka_REDACT_a0e28beff1a695d_ooebmkcb',
startTime=2022-07-13T18:05:25.076Z, remainingSeconds=12},
{id='index_kafka_REDACT_6d9bfea723c33b1_jjjghjno',
startTime=2022-07-13T19:03:11.973Z, remainingSeconds=3479},
{id='index_kafka_REDACT_9e0855d6476c544_hipjneeg',
startTime=2022-07-13T19:03:11.880Z, remainingSeconds=3479},
{id='index_kafka_REDACT_e628ac753b0f515_mifoboff',
startTime=2022-07-13T18:05:25.197Z, remainingSeconds=12},
{id='index_kafka_REDACT_d2c6cae89761257_lcoijmkl',
startTime=2022-07-13T18:06:10.792Z, remainingSeconds=58}], publishing=[{id=
'index_kafka_REDACT_ea10a8905c833a3_hoaimboj',
startTime=2022-07-13T18:00:03.290Z, remainingSeconds=2581},
{id='index_kafka_REDACT_189ca15db9e3918_mengchck',
startTime=2022-07-13T17:57:43.306Z, remainingSeconds=2270},
{id='index_kafka_REDACT_2c04a6043eb3a77_jbofolej',
startTime=2022-07-13T17:57:43.546Z, remainingSeconds=2270}], suspended=false,
healthy=true, state=RUNNING, detailedState=RUNNING,
recentErrors=[ExceptionEvent{timestamp=2022-07-13T19:04:57.475Z,
exceptionClass='org.apache.druid.java.util.common.ISE', message='No such
previous checkpoint
[KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamStartSequenceNumbers{stream='REDACT',
partitionSequenceNumberMap={0=34403769298}, exclusivePartitions=[]}}]
found'}]}}
2022-07-13T19:05:19,387 INFO [KafkaSupervisor-REDACT]
org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor -
{id='REDACT', generationTime=2022-07-13T19:05:19.387Z,
payload=KafkaSupervisorReportPayload{dataSource='REDACT', topic='REDACT',
partitions=6, replicas=1, durationSeconds=3600,
active=[{id='index_kafka_REDACT_b803d3572726dca_joklmebc',
startTime=2022-07-13T19:05:03.970Z, remainingSeconds=3584},
{id='index_kafka_REDACT_a0e28beff1a695d_ooebmkcb',
startTime=2022-07-13T18:05:25.076Z, remainingSeconds=5},
{id='index_kafka_REDACT_6d9bfea723c33b1_jjjghjno',
startTime=2022-07-13T19:03:11.973Z, remainingSeconds=3472},
{id='index_kafka_REDACT_9e0855d6476c544_hipjneeg',
startTime=2022-07-13T19:03:11.880Z, remainingSeconds=3472},
{id='index_kafka_REDACT_e628ac753b0f515_mifoboff',
startTime=2022-07-13T18:05:25.197Z, remainingSeconds=5},
{id='index_kafka_REDACT_d2c6cae89761257_lcoijmkl',
startTime=2022-07-13T18:06:10.792Z, remainingSeconds=51}], publishing=[{id='i
ndex_kafka_REDACT_ea10a8905c833a3_hoaimboj',
startTime=2022-07-13T18:00:03.290Z, remainingSeconds=2574},
{id='index_kafka_REDACT_189ca15db9e3918_mengchck',
startTime=2022-07-13T17:57:43.306Z, remainingSeconds=2263},
{id='index_kafka_REDACT_2c04a6043eb3a77_jbofolej',
startTime=2022-07-13T17:57:43.546Z, remainingSeconds=2263}], suspended=false,
healthy=true, state=RUNNING, detailedState=RUNNING,
recentErrors=[ExceptionEvent{timestamp=2022-07-13T19:04:57.475Z,
exceptionClass='org.apache.druid.java.util.common.ISE', message='No such
previous checkpoint
[KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamStartSequenceNumbers{stream='REDACT',
partitionSequenceNumberMap={0=34403769298}, exclusivePartitions=[]}}]
found'}]}}
2022-07-13T19:05:30,580 INFO [IndexTaskClient-REDACT-5]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskClient - Still
waiting for task [index_kafka_REDACT_e628ac753b0f515_mifoboff] to change its
status to [PAUSED]; will try again in [PT2S]
2022-07-13T19:05:32,586 INFO [IndexTaskClient-REDACT-5]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskClient - Still
waiting for task [index_kafka_REDACT_e628ac753b0f515_mifoboff] to change its
status to [PAUSED]; will try again in [PT4S]
2022-07-13T19:05:36,592 INFO [IndexTaskClient-REDACT-5]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskClient - Still
waiting for task [index_kafka_REDACT_e628ac753b0f515_mifoboff] to change its
status to [PAUSED]; will try again in [PT8S]
2022-07-13T19:05:44,597 INFO [IndexTaskClient-REDACT-5]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskClient - Still
waiting for task [index_kafka_REDACT_e628ac753b0f515_mifoboff] to change its
status to [PAUSED]; will try again in [PT10S]
2022-07-13T19:05:54,609 INFO [IndexTaskClient-REDACT-5]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskClient - Still
waiting for task [index_kafka_REDACT_e628ac753b0f515_mifoboff] to change its
status to [PAUSED]; will try again in [PT10S]
2022-07-13T19:06:04,617 INFO [IndexTaskClient-REDACT-5]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskClient - Still
waiting for task [index_kafka_REDACT_e628ac753b0f515_mifoboff] to change its
status to [PAUSED]; will try again in [PT10S]
2022-07-13T19:06:14,623 INFO [IndexTaskClient-REDACT-5]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskClient - Still
waiting for task [index_kafka_REDACT_e628ac753b0f515_mifoboff] to change its
status to [PAUSED]; will try again in [PT10S]
2022-07-13T19:06:24,633 INFO [IndexTaskClient-REDACT-5]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskClient - Still
waiting for task [index_kafka_REDACT_e628ac753b0f515_mifoboff] to change its
status to [PAUSED]; will try again in [PT10S]
2022-07-13T19:06:34,640 INFO [KafkaSupervisor-REDACT-Worker-2]
org.apache.druid.indexing.overlord.RemoteTaskRunner - Shutdown
[index_kafka_REDACT_e628ac753b0f515_mifoboff] because: [An exception occured
while waiting for task [index_kafka_REDACT_e628ac753b0f515_mifoboff] to pause:
[org.apache.druid.java.util.common.ISE: Task
[index_kafka_REDACT_e628ac753b0f515_mifoboff] failed to change its status from
[READING] to [PAUSED], aborting]]
2022-07-13T19:06:34,649 INFO [KafkaSupervisor-REDACT-Worker-2]
org.apache.druid.indexing.overlord.RemoteTaskRunner - Sent shutdown message to
worker: REDACTED.host.com:8091, status 200 OK, response:
{"task":"index_kafka_REDACT_e628ac753b0f515_mifoboff"}
2022-07-13T19:06:35,604 INFO [Curator-PathChildrenCache-1]
org.apache.druid.indexing.overlord.RemoteTaskRunner -
Worker[REDACTED.host.com:8091] wrote FAILED status for task
[index_kafka_REDACT_e628ac753b0f515_mifoboff] on
[TaskLocation{host='REDACTED.host.com', port=8100, tlsPort=-1}]
2022-07-13T19:06:35,604 INFO [Curator-PathChildrenCache-1]
org.apache.druid.indexing.overlord.RemoteTaskRunner -
Worker[REDACTED.host.com:8091] completed
task[index_kafka_REDACT_e628ac753b0f515_mifoboff] with status[FAILED]
2022-07-13T19:06:35,604 INFO [Curator-PathChildrenCache-1]
org.apache.druid.indexing.overlord.TaskQueue - Received FAILED status for task:
index_kafka_REDACT_e628ac753b0f515_mifoboff
2022-07-13T19:09:36,400 INFO [qtp1886478937-103]
org.apache.druid.indexing.overlord.TaskLockbox -
Task[index_kafka_REDACT_e628ac753b0f515_mifoboff] already present in
TaskLock[index_kafka_REDACT]
2022-07-13T19:11:02,320 INFO [KafkaSupervisor-REDACT-Worker-2]
org.apache.druid.indexing.overlord.TaskLockbox - Removing
task[index_kafka_REDACT_e628ac753b0f515_mifoboff] from activeTasks
2022-07-13T19:11:02,320 INFO [KafkaSupervisor-REDACT-Worker-2]
org.apache.druid.indexing.overlord.TaskLockbox - Removing
task[index_kafka_REDACT_e628ac753b0f515_mifoboff] from
TaskLock[TimeChunkLock{type=EXCLUSIVE, groupId='index_kafka_REDACT',
dataSource='REDACT',
interval=2022-07-13T15:00:00.000Z/2022-07-13T16:00:00.000Z,
version='2022-07-13T17:58:07.642Z', priority=75, revoked=false}]
2022-07-13T19:11:02,357 INFO [KafkaSupervisor-REDACT-Worker-2]
org.apache.druid.indexing.overlord.TaskLockbox - Removing
task[index_kafka_REDACT_e628ac753b0f515_mifoboff] from
TaskLock[TimeChunkLock{type=EXCLUSIVE, groupId='index_kafka_REDACT',
dataSource='REDACT',
interval=2022-07-13T16:00:00.000Z/2022-07-13T17:00:00.000Z,
version='2022-07-13T17:59:13.251Z', priority=75, revoked=false}]
2022-07-13T19:11:02,380 INFO [KafkaSupervisor-REDACT-Worker-2]
org.apache.druid.indexing.overlord.TaskLockbox - Removing
task[index_kafka_REDACT_e628ac753b0f515_mifoboff] from
TaskLock[TimeChunkLock{type=EXCLUSIVE, groupId='index_kafka_REDACT',
dataSource='REDACT',
interval=2022-07-13T17:00:00.000Z/2022-07-13T18:00:00.000Z,
version='2022-07-13T17:58:29.728Z', priority=75, revoked=false}]
2022-07-13T19:11:02,397 INFO [KafkaSupervisor-REDACT-Worker-2]
org.apache.druid.indexing.overlord.TaskLockbox - Removing
task[index_kafka_REDACT_e628ac753b0f515_mifoboff] from
TaskLock[TimeChunkLock{type=EXCLUSIVE, groupId='index_kafka_REDACT',
dataSource='REDACT',
interval=2022-07-13T18:00:00.000Z/2022-07-13T19:00:00.000Z,
version='2022-07-13T18:05:21.125Z', priority=75, revoked=false}]
2022-07-13T19:11:02,424 INFO [KafkaSupervisor-REDACT-Worker-2]
org.apache.druid.indexing.overlord.MetadataTaskStorage - Updating task
index_kafka_REDACT_e628ac753b0f515_mifoboff to status:
TaskStatus{id=index_kafka_REDACT_e628ac753b0f515_mifoboff, status=FAILED,
duration=-1, errorMsg=An exception occured while waiting for task
[index_kafka_REDACT_e628ac753b0f515_mifoboff] to pause: [...}
2022-07-13T19:11:02,458 INFO [KafkaSupervisor-REDACT-Worker-2]
org.apache.druid.indexing.overlord.TaskQueue - Task done:
AbstractTask{id='index_kafka_REDACT_e628ac753b0f515_mifoboff',
groupId='index_kafka_REDACT',
taskResource=TaskResource{availabilityGroup='index_kafka_REDACT_e628ac753b0f515',
requiredCapacity=1}, dataSource='REDACT',
context={checkpoints={"0":{"4":34424090174}},
useLineageBasedSegmentAllocation=true, IS_INCREMENTAL_HANDOFF_SUPPORTED=true,
forceTimeChunkLock=true}}
2022-07-13T19:11:02,458 INFO [Curator-PathChildrenCache-1]
org.apache.druid.indexing.overlord.RemoteTaskRunner - Shutdown
[index_kafka_REDACT_e628ac753b0f515_mifoboff] because: [notified status change
from task]
2022-07-13T19:11:02,458 INFO [Curator-PathChildrenCache-1]
org.apache.druid.indexing.overlord.RemoteTaskRunner - Cleaning up
task[index_kafka_REDACT_e628ac753b0f515_mifoboff] on
worker[REDACTED.host.com:8091]
2022-07-13T19:11:02,461 WARN [Curator-PathChildrenCache-1]
org.apache.druid.indexing.overlord.TaskQueue - Unknown task completed:
index_kafka_REDACT_e628ac753b0f515_mifoboff
2022-07-13T19:11:02,461 INFO [Curator-PathChildrenCache-1]
org.apache.druid.indexing.overlord.TaskQueue - Task FAILED:
AbstractTask{id='index_kafka_REDACT_e628ac753b0f515_mifoboff',
groupId='index_kafka_REDACT',
taskResource=TaskResource{availabilityGroup='index_kafka_REDACT_e628ac753b0f515',
requiredCapacity=1}, dataSource='REDACT',
context={checkpoints={"0":{"4":34424090174}},
useLineageBasedSegmentAllocation=true, IS_INCREMENTAL_HANDOFF_SUPPORTED=true,
forceTimeChunkLock=true}} (3674129 run duration)
2022-07-13T19:11:02,462 INFO [Curator-PathChildrenCache-1]
org.apache.druid.indexing.overlord.RemoteTaskRunner -
Task[index_kafka_REDACT_e628ac753b0f515_mifoboff] went bye bye.
java.lang.RuntimeException: org.apache.druid.java.util.common.ISE: Cannot
find locks for task[index_kafka_REDACT_e628ac753b0f515_mifoboff] and
interval[2022-07-13T17:00:00.000Z/2022-07-13T18:00:00.000Z]
Caused by: org.apache.druid.java.util.common.ISE: Cannot find locks for
task[index_kafka_REDACT_e628ac753b0f515_mifoboff] and
interval[2022-07-13T17:00:00.000Z/2022-07-13T18:00:00.000Z]
```
* Some Peon logs at time of failure:
```
2022-07-13T19:05:13,615 INFO [task-runner-0-priority-0]
org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver - Pushing
[2] segments in background
2022-07-13T19:05:13,615 INFO [task-runner-0-priority-0]
org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver - Pushing
segments:
[REDACT_2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z_2022-07-13T17:20:31.558Z_52,
REDACT_2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z_2022-07-13T18:05:21.125Z_23]
2022-07-13T19:05:13,615 INFO [task-runner-0-priority-0]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator - Persisted
rows[0] and (estimated) bytes[0]
2022-07-13T19:05:13,616 INFO
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-persist]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator - Flushed
in-memory data with commit metadata
[AppenderatorDriverMetadata{segments={index_kafka_REDACT_e628ac753b0f515_6=[SegmentWithState{segmentIdentifier=REDACT_2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z_2022-07-13T17:20:31.558Z_52,
state=APPENDING},
SegmentWithState{segmentIdentifier=REDACT_2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z_2022-07-13T18:05:21.125Z_23,
state=APPENDING}]},
lastSegmentIds={index_kafka_REDACT_e628ac753b0f515_6=REDACT_2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z_2022-07-13T18:05:21.125Z_23},
callerMetadata={nextPartitions=SeekableStreamStartSequenceNumbers{stream='REDACT',
partitionSequenceNumberMap={4=34490690508}, exclusivePartitions=[]},
publishPartitions=SeekableStreamEndSequenceNumbers{stream='REDACT',
partitionSequenceNumberMap={4=34490690508}}}}] for segments:
2022-07-13T19:05:13,616 INFO
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-persist]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator - Persisted
stats: processed rows: [66600334], persisted rows[0], sinks: [2], total
fireHydrants (across sinks): [28], persisted fireHydrants (across sinks): [0]
2022-07-13T19:05:13,617 INFO
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-merge]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator - Preparing
to push (stats): processed rows: [66600334], sinks: [2], fireHydrants (across
sinks): [28]
2022-07-13T19:05:32,041 INFO
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-merge]
org.apache.druid.storage.s3.S3Utils - Pushing
[var/tmp/druid3974223714608681024index.zip] to bucket[lighthouse-prd-druid] and
key[druid/segments/REDACT/2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z/2022-07-13T17:20:31.558Z/52/e389276d-f062-4919-a4c0-b2127d9a1213/index.zip].
2022-07-13T19:05:41,440 INFO
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-merge]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator -
Segment[REDACT_2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z_2022-07-13T17:20:31.558Z_52]
of 42,030,501 bytes built from 14 incremental persist(s) in 15,995ms; pushed
to deep storage in 11,825ms. Load spec is:
{"type":"s3_zip","bucket":"lighthouse-prd-druid","key":"druid/segments/REDACT/2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z/2022-07-13T17:20:31.558Z/52/e389276d-f062-4919-a4c0-b2127d9a1213/index.zip","S3Schema":"s3n"}
2022-07-13T19:05:41,443 INFO
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-merge]
org.apache.druid.segment.IndexMerger - Indexes have incompatible dimension
orders, try falling back on dimension ordering from ingestionSpec
2022-07-13T19:05:41,443 INFO
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-merge]
org.apache.druid.segment.IndexMerger - Cannot fall back on dimension ordering
from ingestionSpec as it does not exist
2022-07-13T19:05:41,443 WARN
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-merge]
org.apache.druid.segment.IndexMerger - Indexes have incompatible dimension
orders and there is no valid dimension ordering in the ingestionSpec, using
lexicographic order.
2022-07-13T19:05:58,734 INFO
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-merge]
org.apache.druid.segment.IndexMerger - Indexes have incompatible dimension
orders, try falling back on dimension ordering from ingestionSpec
2022-07-13T19:05:58,734 INFO
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-merge]
org.apache.druid.segment.IndexMerger - Cannot fall back on dimension ordering
from ingestionSpec as it does not exist
2022-07-13T19:05:58,734 WARN
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-merge]
org.apache.druid.segment.IndexMerger - Indexes have incompatible dimension
orders and there is no valid dimension ordering in the ingestionSpec, using
lexicographic order.
2022-07-13T19:06:01,046 INFO
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-merge]
org.apache.druid.storage.s3.S3Utils - Pushing
[var/tmp/druid4292169727423806480index.zip] to bucket[lighthouse-prd-druid] and
key[druid/segments/REDACT/2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z/2022-07-13T18:05:21.125Z/23/6df99ac1-2433-4abd-a7b4-0fe1eb8a7298/index.zip].
2022-07-13T19:06:09,644 INFO
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-merge]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator -
Segment[REDACT_2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z_2022-07-13T18:05:21.125Z_23]
of 40,001,434 bytes built from 14 incremental persist(s) in 17,290ms; pushed
to deep storage in 10,909ms. Load spec is:
{"type":"s3_zip","bucket":"lighthouse-prd-druid","key":"druid/segments/REDACT/2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z/2022-07-13T18:05:21.125Z/23/6df99ac1-2433-4abd-a7b4-0fe1eb8a7298/index.zip","S3Schema":"s3n"}
2022-07-13T19:06:09,644 INFO
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-merge]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator - Push
complete...
2022-07-13T19:06:34,643 INFO [parent-monitor-0]
org.apache.druid.indexing.worker.executor.ExecutorLifecycle - Triggering JVM
shutdown.
2022-07-13T19:06:34,644 INFO [Thread-70] org.apache.druid.cli.CliPeon -
Running shutdown hook
2022-07-13T19:06:34,644 INFO [Thread-70]
org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle
[module] stage [ANNOUNCEMENTS]
2022-07-13T19:06:34,650 INFO [Thread-70]
org.apache.druid.curator.announcement.Announcer - Unannouncing
[/druid/announcements/REDACTED.host.com:8100]
2022-07-13T19:06:34,660 INFO [Thread-70]
org.apache.druid.curator.announcement.Announcer - Unannouncing
[/druid/segments/REDACTED.host.com:8100/REDACTED.host.com:8100_indexer-executor__default_tier_2022-07-13T18:06:23.466Z_94eb07774ad34af4b479f12e11663b9d0]
2022-07-13T19:06:34,663 INFO [Thread-70]
org.apache.druid.curator.announcement.Announcer - Unannouncing
[/druid/internal-discovery/PEON/REDACTED.host.com:8100]
2022-07-13T19:06:34,666 INFO [Thread-70]
org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle
[module] stage [SERVER]
2022-07-13T19:06:34,672 INFO [Thread-70]
org.eclipse.jetty.server.AbstractConnector - Stopped
ServerConnector@70cd122{HTTP/1.1, (http/1.1)}{0.0.0.0:8100}
2022-07-13T19:06:34,672 INFO [Thread-70] org.eclipse.jetty.server.session -
node0 Stopped scavenging
2022-07-13T19:06:34,673 INFO [Thread-70]
org.eclipse.jetty.server.handler.ContextHandler - Stopped
o.e.j.s.ServletContextHandler@5a6af2c4{/,null,STOPPED}
2022-07-13T19:06:34,674 INFO [Thread-70]
org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle
[module] stage [NORMAL]
2022-07-13T19:06:34,675 INFO [Thread-70]
org.apache.druid.server.coordination.ZkCoordinator - Stopping ZkCoordinator for
[DruidServerMetadata{name='REDACTED.host.com:8100',
hostAndPort='REDACTED.host.com:8100', hostAndTlsPort='null', maxSize=0,
tier='_default_tier', type=indexer-executor, priority=0}]
2022-07-13T19:06:34,675 INFO [Thread-70]
org.apache.druid.server.coordination.SegmentLoadDropHandler - Stopping...
2022-07-13T19:06:34,675 INFO [Thread-70]
org.apache.druid.server.coordination.SegmentLoadDropHandler - Stopped.
2022-07-13T19:06:34,675 INFO [Thread-70]
org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner - Starting
graceful shutdown of task[index_kafka_REDACT_e628ac753b0f515_mifoboff].
2022-07-13T19:06:34,675 INFO [Thread-70]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner -
Stopping forcefully (status: [READING])
2022-07-13T19:06:34,676 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.23.0.jar:0.23.0]
at
org.apache.druid.indexing.appenderator.ActionBasedSegmentAllocator.allocate(ActionBasedSegmentAllocator.java:57)
~[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver.getSegment(BaseAppenderatorDriver.java:338)
~[druid-server-0.23.0.jar:0.23.0]
at
org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver.append(BaseAppenderatorDriver.java:407)
~[druid-server-0.23.0.jar:0.23.0]
at
org.apache.druid.segment.realtime.appenderator.StreamAppenderatorDriver.add(StreamAppenderatorDriver.java:189)
~[druid-server-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner.runInternal(SeekableStreamIndexTaskRunner.java:652)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner.run(SeekableStreamIndexTaskRunner.java:265)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTask.run(SeekableStreamIndexTask.java:149)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner$SingleTaskBackgroundRunnerCallable.call(SingleTaskBackgroundRunner.java:477)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner$SingleTaskBackgroundRunnerCallable.call(SingleTaskBackgroundRunner.java:449)
[druid-indexing-service-0.23.0.jar:0.23.0]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[?:1.8.0_322]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[?:1.8.0_322]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[?:1.8.0_322]
at java.lang.Thread.run(Thread.java:750) [?:1.8.0_322]
Caused by: java.lang.InterruptedException
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:998)
~[?:1.8.0_322]
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
~[?:1.8.0_322]
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:143)
~[druid-server-0.23.0.jar:0.23.0]
at
org.apache.druid.discovery.DruidLeaderClient.go(DruidLeaderClient.java:127)
~[druid-server-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.common.actions.RemoteTaskActionClient.submit(RemoteTaskActionClient.java:82)
~[druid-indexing-service-0.23.0.jar:0.23.0]
... 13 more
2022-07-13T19:06:34,677 INFO [task-runner-0-priority-0]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator - Persisted
rows[0] and (estimated) bytes[0]
2022-07-13T19:06:34,678 INFO [task-runner-0-priority-0]
org.apache.kafka.clients.consumer.internals.ConsumerCoordinator - [Consumer
clientId=consumer-kafka-supervisor-oimpihlj-1,
groupId=kafka-supervisor-oimpihlj] Resetting generation due to: consumer
pro-actively leaving the group
2022-07-13T19:06:34,678 INFO [task-runner-0-priority-0]
org.apache.kafka.clients.consumer.internals.ConsumerCoordinator - [Consumer
clientId=consumer-kafka-supervisor-oimpihlj-1,
groupId=kafka-supervisor-oimpihlj] Request joining group due to: consumer
pro-actively leaving the group
2022-07-13T19:06:34,678 INFO
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-persist]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator - Flushed
in-memory data with commit metadata
[AppenderatorDriverMetadata{segments={index_kafka_REDACT_e628ac753b0f515_6=[SegmentWithState{segmentIdentifier=REDACT_2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z_2022-07-13T17:20:31.558Z_52,
state=APPENDING},
SegmentWithState{segmentIdentifier=REDACT_2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z_2022-07-13T18:05:21.125Z_23,
state=APPENDING}]},
lastSegmentIds={index_kafka_REDACT_e628ac753b0f515_6=REDACT_2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z_2022-07-13T18:05:21.125Z_23},
callerMetadata={nextPartitions=SeekableStreamEndSequenceNumbers{stream='REDACT',
partitionSequenceNumberMap={4=34490690508}}}}] for segments:
2022-07-13T19:06:34,678 INFO
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-appenderator-persist]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator - Persisted
stats: processed rows: [66600334], persisted rows[0], sinks: [2], total
fireHydrants (across sinks): [28], persisted fireHydrants (across sinks): [0]
2022-07-13T19:06:34,678 INFO [task-runner-0-priority-0]
org.apache.kafka.common.metrics.Metrics - Metrics scheduler closed
2022-07-13T19:06:34,678 INFO [task-runner-0-priority-0]
org.apache.kafka.common.metrics.Metrics - Closing reporter
org.apache.kafka.common.metrics.JmxReporter
2022-07-13T19:06:34,678 INFO [task-runner-0-priority-0]
org.apache.kafka.common.metrics.Metrics - Metrics reporters closed
2022-07-13T19:06:34,681 INFO [task-runner-0-priority-0]
org.apache.kafka.common.utils.AppInfoParser - App info kafka.consumer for
consumer-kafka-supervisor-oimpihlj-1 unregistered
2022-07-13T19:06:34,683 ERROR [task-runner-0-priority-0]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner - Error
while publishing segments for sequenceNumber[SequenceMetadata{sequenceId=6,
sequenceName='index_kafka_REDACT_e628ac753b0f515_6', assignments=[],
startOffsets={4=34481031936}, exclusiveStartPartitions=[],
endOffsets={4=34490690508}, sentinel=false, checkpointed=true}]
java.util.concurrent.CancellationException: Task was cancelled.
at
com.google.common.util.concurrent.AbstractFuture.cancellationExceptionWithCause(AbstractFuture.java:392)
~[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.AbstractFuture$Sync.getValue(AbstractFuture.java:306)
~[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:286)
~[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116)
~[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.Uninterruptibles.getUninterruptibly(Uninterruptibles.java:135)
~[guava-16.0.1.jar:?]
at com.google.common.util.concurrent.Futures$4.run(Futures.java:1170)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.MoreExecutors$SameThreadExecutorService.execute(MoreExecutors.java:297)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:145)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.AbstractFuture.cancel(AbstractFuture.java:134)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.Futures$ChainingListenableFuture.cancel(Futures.java:826)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.Futures$CombinedFuture$1.run(Futures.java:1505)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.MoreExecutors$SameThreadExecutorService.execute(MoreExecutors.java:297)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:145)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.AbstractFuture.cancel(AbstractFuture.java:134)
[guava-16.0.1.jar:?]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner.runInternal(SeekableStreamIndexTaskRunner.java:885)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner.run(SeekableStreamIndexTaskRunner.java:265)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTask.run(SeekableStreamIndexTask.java:149)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner$SingleTaskBackgroundRunnerCallable.call(SingleTaskBackgroundRunner.java:477)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner$SingleTaskBackgroundRunnerCallable.call(SingleTaskBackgroundRunner.java:449)
[druid-indexing-service-0.23.0.jar:0.23.0]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[?:1.8.0_322]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[?:1.8.0_322]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[?:1.8.0_322]
at java.lang.Thread.run(Thread.java:750) [?:1.8.0_322]
Caused by: java.util.concurrent.CancellationException: Future.cancel() was
called.
at
com.google.common.util.concurrent.AbstractFuture$Sync.complete(AbstractFuture.java:378)
~[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.AbstractFuture$Sync.cancel(AbstractFuture.java:355)
~[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.AbstractFuture.cancel(AbstractFuture.java:131)
~[guava-16.0.1.jar:?]
... 15 more
2022-07-13T19:06:34,683 WARN
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-publish]
org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver - Failed
publish (java.lang.RuntimeException: java.lang.InterruptedException)
2022-07-13T19:06:34,684 INFO [task-runner-0-priority-0]
org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Unannouncing
segment[REDACT_2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z_2022-07-13T17:20:31.558Z_52]
at
path[/druid/segments/REDACTED.host.com:8100/REDACTED.host.com:8100_indexer-executor__default_tier_2022-07-13T18:06:23.466Z_94eb07774ad34af4b479f12e11663b9d0]
2022-07-13T19:06:34,685 INFO [task-runner-0-priority-0]
org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Unannouncing
segment[REDACT_2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z_2022-07-13T18:05:21.125Z_23]
at
path[/druid/segments/REDACTED.host.com:8100/REDACTED.host.com:8100_indexer-executor__default_tier_2022-07-13T18:06:23.466Z_94eb07774ad34af4b479f12e11663b9d0]
2022-07-13T19:06:34,688 INFO
[LookupExtractorFactoryContainerProvider-MainThread]
org.apache.druid.query.lookup.LookupReferencesManager - Lookup Management loop
exited. Lookup notices are not handled anymore.
2022-07-13T19:06:34,690 WARN
[[index_kafka_REDACT_e628ac753b0f515_mifoboff]-publish]
org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver - Failed
publish, not removing segments:
[REDACT_2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z_2022-07-13T17:20:31.558Z_52,
REDACT_2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z_2022-07-13T18:05:21.125Z_23]
2022-07-13T19:06:34,690 INFO [task-runner-0-priority-0]
org.apache.druid.curator.discovery.CuratorDruidNodeAnnouncer - Unannounced self
[{"druidNode":{"service":"druid/middleManager","host":"REDACTED.host.com","bindOnHost":false,"plaintextPort":8100,"port":-1,"tlsPort":-1,"enablePlaintextPort":true,"enableTlsPort":false},"nodeType":"peon","services":{"dataNodeService":{"type":"dataNodeService","tier":"_default_tier","maxSize":0,"type":"indexer-executor","serverType":"indexer-executor","priority":0},"lookupNodeService":{"type":"lookupNodeService","lookupTier":"__default"}}}].
2022-07-13T19:06:34,690 ERROR [task-runner-0-priority-0]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner -
Encountered exception while running task.
java.lang.RuntimeException: java.lang.InterruptedException
at
org.apache.druid.indexing.common.actions.RemoteTaskActionClient.submit(RemoteTaskActionClient.java:125)
~[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.appenderator.ActionBasedSegmentAllocator.allocate(ActionBasedSegmentAllocator.java:57)
~[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver.getSegment(BaseAppenderatorDriver.java:338)
~[druid-server-0.23.0.jar:0.23.0]
at
org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver.append(BaseAppenderatorDriver.java:407)
~[druid-server-0.23.0.jar:0.23.0]
at
org.apache.druid.segment.realtime.appenderator.StreamAppenderatorDriver.add(StreamAppenderatorDriver.java:189)
~[druid-server-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner.runInternal(SeekableStreamIndexTaskRunner.java:652)
~[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner.run(SeekableStreamIndexTaskRunner.java:265)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTask.run(SeekableStreamIndexTask.java:149)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner$SingleTaskBackgroundRunnerCallable.call(SingleTaskBackgroundRunner.java:477)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner$SingleTaskBackgroundRunnerCallable.call(SingleTaskBackgroundRunner.java:449)
[druid-indexing-service-0.23.0.jar:0.23.0]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[?:1.8.0_322]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[?:1.8.0_322]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[?:1.8.0_322]
at java.lang.Thread.run(Thread.java:750) [?:1.8.0_322]
Suppressed: java.lang.InterruptedException
at
java.util.concurrent.FutureTask.awaitDone(FutureTask.java:404) ~[?:1.8.0_322]
at java.util.concurrent.FutureTask.get(FutureTask.java:191)
~[?:1.8.0_322]
at
org.apache.druid.segment.realtime.appenderator.StreamAppenderatorDriver.persist(StreamAppenderatorDriver.java:233)
~[druid-server-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner.runInternal(SeekableStreamIndexTaskRunner.java:770)
~[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner.run(SeekableStreamIndexTaskRunner.java:265)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTask.run(SeekableStreamIndexTask.java:149)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner$SingleTaskBackgroundRunnerCallable.call(SingleTaskBackgroundRunner.java:477)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner$SingleTaskBackgroundRunnerCallable.call(SingleTaskBackgroundRunner.java:449)
[druid-indexing-service-0.23.0.jar:0.23.0]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[?:1.8.0_322]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[?:1.8.0_322]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[?:1.8.0_322]
at java.lang.Thread.run(Thread.java:750) [?:1.8.0_322]
Caused by: java.lang.InterruptedException
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:998)
~[?:1.8.0_322]
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
~[?:1.8.0_322]
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:143)
~[druid-server-0.23.0.jar:0.23.0]
at
org.apache.druid.discovery.DruidLeaderClient.go(DruidLeaderClient.java:127)
~[druid-server-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.common.actions.RemoteTaskActionClient.submit(RemoteTaskActionClient.java:82)
~[druid-indexing-service-0.23.0.jar:0.23.0]
... 13 more
2022-07-13T19:06:34,692 INFO [Curator-Framework-0]
org.apache.curator.framework.imps.CuratorFrameworkImpl -
backgroundOperationsLoop exiting
2022-07-13T19:06:34,697 INFO [task-runner-0-priority-0]
org.apache.druid.indexing.worker.executor.ExecutorLifecycle - Task completed
with status: {
"id" : "index_kafka_REDACT_e628ac753b0f515_mifoboff",
"status" : "FAILED",
"duration" : 3669508,
"errorMsg" : "java.lang.RuntimeException:
java.lang.InterruptedException\n\tat org.apache.druid.indexing.common.acti...",
"location" : {
"host" : null,
"port" : -1,
"tlsPort" : -1
}
}
2022-07-13T19:06:34,700 INFO [main] org.apache.druid.cli.CliPeon - Thread
[Thread[pool-3-thread-4,5,main]] is non daemon.
2022-07-13T19:06:34,700 INFO [main] org.apache.druid.cli.CliPeon - Thread
[Thread[Thread-70,5,main]] is non daemon.
2022-07-13T19:06:34,700 INFO [main] org.apache.druid.cli.CliPeon - Thread
[Thread[pool-3-thread-3,5,main]] is non daemon.
2022-07-13T19:06:34,700 INFO [main] org.apache.druid.cli.CliPeon - Thread
[Thread[pool-3-thread-1,5,main]] is non daemon.
2022-07-13T19:06:34,700 INFO [main] org.apache.druid.cli.CliPeon - Thread
[Thread[pool-3-thread-2,5,main]] is non daemon.
2022-07-13T19:06:34,700 INFO [main]
org.apache.druid.java.util.common.lifecycle.Lifecycle - Lifecycle [module]
already stopped and stop was called. Silently skipping
Cannot remove shutdown hook, already shutting down!
Finished peon task
```
2. Task: `index_kafka_REDACT_a0e28beff1a695d_ooebmkcb`, start time:
`2022-07-13T18:05:21,994`, was in `PUBLISHING` state
* Some Overlord logs:
```
2022-07-13T19:05:19,387 INFO [KafkaSupervisor-REDACT]
org.apache.druid.indexing.seekablestream.supervisor.SeekableStreamSupervisor -
{id='REDACT', generationTime=2022-07-13T19:05:19.387Z,
payload=KafkaSupervisorReportPayload{dataSource='REDACT', topic='REDACT',
partitions=6, replicas=1, durationSeconds=3600,
active=[{id='index_kafka_REDACT_b803d3572726dca_joklmebc',
startTime=2022-07-13T19:05:03.970Z, remainingSeconds=3584},
{id='index_kafka_REDACT_a0e28beff1a695d_ooebmkcb',
startTime=2022-07-13T18:05:25.076Z, remainingSeconds=5},
{id='index_kafka_REDACT_6d9bfea723c33b1_jjjghjno',
startTime=2022-07-13T19:03:11.973Z, remainingSeconds=3472},
{id='index_kafka_REDACT_9e0855d6476c544_hipjneeg',
startTime=2022-07-13T19:03:11.880Z, remainingSeconds=3472},
{id='index_kafka_REDACT_e628ac753b0f515_mifoboff',
startTime=2022-07-13T18:05:25.197Z, remainingSeconds=5},
{id='index_kafka_REDACT_d2c6cae89761257_lcoijmkl',
startTime=2022-07-13T18:06:10.792Z, remainingSeconds=51}], publishing=[{id='i
ndex_kafka_REDACT_ea10a8905c833a3_hoaimboj',
startTime=2022-07-13T18:00:03.290Z, remainingSeconds=2574},
{id='index_kafka_REDACT_189ca15db9e3918_mengchck',
startTime=2022-07-13T17:57:43.306Z, remainingSeconds=2263},
{id='index_kafka_REDACT_2c04a6043eb3a77_jbofolej',
startTime=2022-07-13T17:57:43.546Z, remainingSeconds=2263}], suspended=false,
healthy=true, state=RUNNING, detailedState=RUNNING,
recentErrors=[ExceptionEvent{timestamp=2022-07-13T19:04:57.475Z,
exceptionClass='org.apache.druid.java.util.common.ISE', message='No such
previous checkpoint
[KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamStartSequenceNumbers{stream='REDACT',
partitionSequenceNumberMap={0=34403769298}, exclusivePartitions=[]}}]
found'}]}}
2022-07-13T19:05:28,767 INFO [IndexTaskClient-REDACT-0]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskClient - Task
[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb] paused successfully
2022-07-13T19:11:05,485 INFO [KafkaSupervisor-REDACT-Worker-0]
org.apache.druid.indexing.overlord.RemoteTaskRunner - Shutdown
[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb] because: [An exception occured
while waiting for task [index_kafka_REDACT_a0e28beff1a695d_ooebmkcb] to pause:
[org.apache.druid.java.util.common.IAE: Received server error with status [400
Bad Request]; first 1KB of body: Can't pause, task is not in a pausable state
(state: [PUBLISHING])]]
2022-07-13T19:11:05,605 INFO [KafkaSupervisor-REDACT-Worker-0]
org.apache.druid.indexing.overlord.RemoteTaskRunner - Sent shutdown message to
worker: REDACTED.host.com:8091, status 200 OK, response:
{"task":"index_kafka_REDACT_a0e28beff1a695d_ooebmkcb"}
2022-07-13T19:11:27,423 INFO [IndexTaskClient-REDACT-0]
org.apache.druid.indexing.common.IndexTaskClient - submitRequest failed for
[http://REDACTED.host.com:8100/druid/worker/v1/chat/index_kafka_REDACT_a0e28beff1a695d_ooebmkcb/offsets/current]
(java.net.ConnectException: Connection refused (Connection refused))
2022-07-13T19:11:57,602 INFO [IndexTaskClient-REDACT-2]
org.apache.druid.indexing.common.IndexTaskClient - submitRequest failed for
[http://REDACTED.host.com:8100/druid/worker/v1/chat/index_kafka_REDACT_a0e28beff1a695d_ooebmkcb/offsets/current]
(java.net.ConnectException: Connection refused (Connection refused))
2022-07-13T19:12:27,784 INFO [IndexTaskClient-REDACT-4]
org.apache.druid.indexing.common.IndexTaskClient - submitRequest failed for
[http://REDACTED.host.com:8100/druid/worker/v1/chat/index_kafka_REDACT_a0e28beff1a695d_ooebmkcb/offsets/current]
(java.net.ConnectException: Connection refused (Connection refused))
2022-07-13T19:12:57,957 INFO [IndexTaskClient-REDACT-3]
org.apache.druid.indexing.common.IndexTaskClient - submitRequest failed for
[http://REDACTED.host.com:8100/druid/worker/v1/chat/index_kafka_REDACT_a0e28beff1a695d_ooebmkcb/offsets/current]
(java.net.ConnectException: Connection refused (Connection refused))
2022-07-13T19:13:14,877 INFO [KafkaSupervisor-REDACT-Worker-0]
org.apache.druid.indexing.overlord.TaskLockbox - Removing
task[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb] from activeTasks
2022-07-13T19:13:14,877 INFO [KafkaSupervisor-REDACT-Worker-0]
org.apache.druid.indexing.overlord.TaskLockbox - Removing
task[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb] from
TaskLock[TimeChunkLock{type=EXCLUSIVE, groupId='index_kafka_REDACT',
dataSource='REDACT',
interval=2022-07-13T15:00:00.000Z/2022-07-13T16:00:00.000Z,
version='2022-07-13T17:58:07.642Z', priority=75, revoked=false}]
2022-07-13T19:13:14,921 INFO [KafkaSupervisor-REDACT-Worker-0]
org.apache.druid.indexing.overlord.TaskLockbox - Removing
task[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb] from
TaskLock[TimeChunkLock{type=EXCLUSIVE, groupId='index_kafka_REDACT',
dataSource='REDACT',
interval=2022-07-13T16:00:00.000Z/2022-07-13T17:00:00.000Z,
version='2022-07-13T17:59:13.251Z', priority=75, revoked=false}]
2022-07-13T19:13:14,935 INFO [KafkaSupervisor-REDACT-Worker-0]
org.apache.druid.indexing.overlord.TaskLockbox - Removing
task[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb] from
TaskLock[TimeChunkLock{type=EXCLUSIVE, groupId='index_kafka_REDACT',
dataSource='REDACT',
interval=2022-07-13T17:00:00.000Z/2022-07-13T18:00:00.000Z,
version='2022-07-13T17:58:29.728Z', priority=75, revoked=false}]
2022-07-13T19:13:14,950 INFO [KafkaSupervisor-REDACT-Worker-0]
org.apache.druid.indexing.overlord.TaskLockbox - Removing
task[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb] from
TaskLock[TimeChunkLock{type=EXCLUSIVE, groupId='index_kafka_REDACT',
dataSource='REDACT',
interval=2022-07-13T18:00:00.000Z/2022-07-13T19:00:00.000Z,
version='2022-07-13T18:05:21.125Z', priority=75, revoked=false}]
2022-07-13T19:13:14,968 INFO [KafkaSupervisor-REDACT-Worker-0]
org.apache.druid.indexing.overlord.MetadataTaskStorage - Updating task
index_kafka_REDACT_a0e28beff1a695d_ooebmkcb to status:
TaskStatus{id=index_kafka_REDACT_a0e28beff1a695d_ooebmkcb, status=FAILED,
duration=-1, errorMsg=An exception occured while waiting for task
[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb] to pause: [...}
2022-07-13T19:13:14,991 INFO [KafkaSupervisor-REDACT-Worker-0]
org.apache.druid.indexing.overlord.TaskQueue - Task done:
AbstractTask{id='index_kafka_REDACT_a0e28beff1a695d_ooebmkcb',
groupId='index_kafka_REDACT',
taskResource=TaskResource{availabilityGroup='index_kafka_REDACT_a0e28beff1a695d',
requiredCapacity=1}, dataSource='REDACT',
context={checkpoints={"0":{"1":34473873410}},
useLineageBasedSegmentAllocation=true, IS_INCREMENTAL_HANDOFF_SUPPORTED=true,
forceTimeChunkLock=true}}
2022-07-13T19:15:50,022 INFO [TaskQueue-Manager]
org.apache.druid.indexing.overlord.RemoteTaskRunner - Shutdown
[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb] because: [Task is not in
knownTaskIds]
2022-07-13T19:15:50,138 INFO [TaskQueue-Manager]
org.apache.druid.indexing.overlord.RemoteTaskRunner - Sent shutdown message to
worker: REDACTED.host.com:8091, status 200 OK, response:
{"task":"index_kafka_REDACT_a0e28beff1a695d_ooebmkcb"}
```
* Some Peon logs at time of failure:
```
2022-07-13T19:05:32,993 INFO [task-runner-0-priority-0]
org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver - Pushing
[3] segments in background
2022-07-13T19:05:32,993 INFO [task-runner-0-priority-0]
org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver - Pushing
segments:
[REDACT_2022-07-13T16:00:00.000Z_2022-07-13T17:00:00.000Z_2022-07-13T16:03:18.415Z_65,
REDACT_2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z_2022-07-13T17:20:31.558Z_54,
REDACT_2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z_2022-07-13T18:05:21.125Z_24]
2022-07-13T19:05:32,993 INFO [task-runner-0-priority-0]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator - Persisted
rows[0] and (estimated) bytes[0]
2022-07-13T19:05:32,994 INFO
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-persist]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator - Flushed
in-memory data with commit metadata
[AppenderatorDriverMetadata{segments={index_kafka_REDACT_a0e28beff1a695d_4=[SegmentWithState{segmentIdentifier=REDACT_2022-07-13T16:00:00.000Z_2022-07-13T17:00:00.000Z_2022-07-13T16:03:18.415Z_65,
state=APPENDING},
SegmentWithState{segmentIdentifier=REDACT_2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z_2022-07-13T17:20:31.558Z_54,
state=APPENDING},
SegmentWithState{segmentIdentifier=REDACT_2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z_2022-07-13T18:05:21.125Z_24,
state=APPENDING}]},
lastSegmentIds={index_kafka_REDACT_a0e28beff1a695d_4=REDACT_2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z_2022-07-13T18:05:21.125Z_24},
callerMetadata={nextPartitions=SeekableStreamStartSequenceNumbers{stream='REDACT',
partitionSequenceNumberMap={1=34517938994}, exclusivePartitions=[]}
, publishPartitions=SeekableStreamEndSequenceNumbers{stream='REDACT',
partitionSequenceNumberMap={1=34517938994}}}}] for segments:
2022-07-13T19:05:32,994 INFO
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-persist]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator - Persisted
stats: processed rows: [44065584], persisted rows[0], sinks: [3], total
fireHydrants (across sinks): [14], persisted fireHydrants (across sinks): [0]
2022-07-13T19:05:32,995 INFO
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-merge]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator - Preparing
to push (stats): processed rows: [44065584], sinks: [3], fireHydrants (across
sinks): [14]
2022-07-13T19:05:32,997 INFO
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-merge]
org.apache.druid.segment.IndexMerger - Indexes have incompatible dimension
orders, try falling back on dimension ordering from ingestionSpec
2022-07-13T19:05:32,997 INFO
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-merge]
org.apache.druid.segment.IndexMerger - Cannot fall back on dimension ordering
from ingestionSpec as it does not exist
2022-07-13T19:05:32,997 WARN
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-merge]
org.apache.druid.segment.IndexMerger - Indexes have incompatible dimension
orders and there is no valid dimension ordering in the ingestionSpec, using
lexicographic order.
2022-07-13T19:05:36,691 INFO
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-merge]
org.apache.druid.segment.IndexMerger - Indexes have incompatible dimension
orders, try falling back on dimension ordering from ingestionSpec
2022-07-13T19:05:36,691 INFO
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-merge]
org.apache.druid.segment.IndexMerger - Cannot fall back on dimension ordering
from ingestionSpec as it does not exist
2022-07-13T19:05:36,691 WARN
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-merge]
org.apache.druid.segment.IndexMerger - Indexes have incompatible dimension
orders and there is no valid dimension ordering in the ingestionSpec, using
lexicographic order.
2022-07-13T19:05:37,247 INFO
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-merge]
org.apache.druid.storage.s3.S3Utils - Pushing
[var/tmp/druid3380072052232269972index.zip] to bucket[lighthouse-prd-druid] and
key[druid/segments/REDACT/2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z/2022-07-13T18:05:21.125Z/24/3dcd0fab-52a4-4dcd-8e73-8f5bb4c686d6/index.zip].
2022-07-13T19:05:38,999 INFO
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-merge]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator -
Segment[REDACT_2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z_2022-07-13T18:05:21.125Z_24]
of 9,601,654 bytes built from 6 incremental persist(s) in 3,694ms; pushed to
deep storage in 2,308ms. Load spec is:
{"type":"s3_zip","bucket":"lighthouse-prd-druid","key":"druid/segments/REDACT/2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z/2022-07-13T18:05:21.125Z/24/3dcd0fab-52a4-4dcd-8e73-8f5bb4c686d6/index.zip","S3Schema":"s3n"}
2022-07-13T19:05:47,972 INFO
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-merge]
org.apache.druid.storage.s3.S3Utils - Pushing
[var/tmp/druid4825400617703327325index.zip] to bucket[lighthouse-prd-druid] and
key[druid/segments/REDACT/2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z/2022-07-13T17:20:31.558Z/54/0c124ebb-9c89-4d9d-abe0-040b47156a74/index.zip].
2022-07-13T19:05:51,484 INFO
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-merge]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator -
Segment[REDACT_2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z_2022-07-13T17:20:31.558Z_54]
of 18,939,906 bytes built from 6 incremental persist(s) in 7,904ms; pushed to
deep storage in 4,577ms. Load spec is:
{"type":"s3_zip","bucket":"lighthouse-prd-druid","key":"druid/segments/REDACT/2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z/2022-07-13T17:20:31.558Z/54/0c124ebb-9c89-4d9d-abe0-040b47156a74/index.zip","S3Schema":"s3n"}
2022-07-13T19:05:53,220 INFO
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-merge]
org.apache.druid.storage.s3.S3Utils - Pushing
[var/tmp/druid7166076608607089797index.zip] to bucket[lighthouse-prd-druid] and
key[druid/segments/REDACT/2022-07-13T16:00:00.000Z_2022-07-13T17:00:00.000Z/2022-07-13T16:03:18.415Z/65/0c5bd870-5837-4888-8c51-08416406bd91/index.zip].
2022-07-13T19:05:53,971 INFO
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-merge]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator -
Segment[REDACT_2022-07-13T16:00:00.000Z_2022-07-13T17:00:00.000Z_2022-07-13T16:03:18.415Z_65]
of 3,257,493 bytes built from 2 incremental persist(s) in 1,518ms; pushed to
deep storage in 966ms. Load spec is:
{"type":"s3_zip","bucket":"lighthouse-prd-druid","key":"druid/segments/REDACT/2022-07-13T16:00:00.000Z_2022-07-13T17:00:00.000Z/2022-07-13T16:03:18.415Z/65/0c5bd870-5837-4888-8c51-08416406bd91/index.zip","S3Schema":"s3n"}
2022-07-13T19:05:53,971 INFO
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-appenderator-merge]
org.apache.druid.segment.realtime.appenderator.StreamAppenderator - Push
complete...
2022-07-13T19:11:05,570 INFO [parent-monitor-0]
org.apache.druid.indexing.worker.executor.ExecutorLifecycle - Triggering JVM
shutdown.
2022-07-13T19:11:05,571 INFO [Thread-70] org.apache.druid.cli.CliPeon -
Running shutdown hook
2022-07-13T19:11:05,571 INFO [Thread-70]
org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle
[module] stage [ANNOUNCEMENTS]
2022-07-13T19:11:05,577 INFO [Thread-70]
org.apache.druid.curator.announcement.Announcer - Unannouncing
[/druid/announcements/REDACTED.host.com:8100]
2022-07-13T19:11:05,746 INFO [Thread-70]
org.apache.druid.curator.announcement.Announcer - Unannouncing
[/druid/segments/REDACTED.host.com:8100/REDACTED.host.com:8100_indexer-executor__default_tier_2022-07-13T18:06:45.560Z_b68d050f95e2471886c2569f2c7b70910]
2022-07-13T19:11:05,805 INFO [Thread-70]
org.apache.druid.curator.announcement.Announcer - Unannouncing
[/druid/internal-discovery/PEON/REDACTED.host.com:8100]
2022-07-13T19:11:05,864 INFO [Thread-70]
org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle
[module] stage [SERVER]
2022-07-13T19:11:05,870 INFO [Thread-70]
org.eclipse.jetty.server.AbstractConnector - Stopped
ServerConnector@59b1edab{HTTP/1.1, (http/1.1)}{0.0.0.0:8100}
2022-07-13T19:11:05,870 INFO [Thread-70] org.eclipse.jetty.server.session -
node0 Stopped scavenging
2022-07-13T19:11:05,871 INFO [Thread-70]
org.eclipse.jetty.server.handler.ContextHandler - Stopped
o.e.j.s.ServletContextHandler@1203d787{/,null,STOPPED}
2022-07-13T19:11:05,874 INFO [Thread-70]
org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle
[module] stage [NORMAL]
2022-07-13T19:11:05,874 INFO [Thread-70]
org.apache.druid.server.coordination.ZkCoordinator - Stopping ZkCoordinator for
[DruidServerMetadata{name='REDACTED.host.com:8100',
hostAndPort='REDACTED.host.com:8100', hostAndTlsPort='null', maxSize=0,
tier='_default_tier', type=indexer-executor, priority=0}]
2022-07-13T19:11:05,875 INFO [Thread-70]
org.apache.druid.server.coordination.SegmentLoadDropHandler - Stopping...
2022-07-13T19:11:05,875 INFO [Thread-70]
org.apache.druid.server.coordination.SegmentLoadDropHandler - Stopped.
2022-07-13T19:11:05,875 INFO [Thread-70]
org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner - Starting
graceful shutdown of task[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb].
2022-07-13T19:11:05,875 INFO [Thread-70]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner -
Stopping forcefully (status: [PUBLISHING])
2022-07-13T19:11:05,875 INFO [task-runner-0-priority-0]
org.apache.kafka.clients.consumer.internals.ConsumerCoordinator - [Consumer
clientId=consumer-kafka-supervisor-eomampef-1,
groupId=kafka-supervisor-eomampef] Resetting generation due to: consumer
pro-actively leaving the group
2022-07-13T19:11:05,875 INFO [task-runner-0-priority-0]
org.apache.kafka.clients.consumer.internals.ConsumerCoordinator - [Consumer
clientId=consumer-kafka-supervisor-eomampef-1,
groupId=kafka-supervisor-eomampef] Request joining group due to: consumer
pro-actively leaving the group
2022-07-13T19:11:05,876 INFO [task-runner-0-priority-0]
org.apache.kafka.common.metrics.Metrics - Metrics scheduler closed
2022-07-13T19:11:05,876 INFO [task-runner-0-priority-0]
org.apache.kafka.common.metrics.Metrics - Closing reporter
org.apache.kafka.common.metrics.JmxReporter
2022-07-13T19:11:05,876 INFO [task-runner-0-priority-0]
org.apache.kafka.common.metrics.Metrics - Metrics reporters closed
2022-07-13T19:11:05,878 INFO [task-runner-0-priority-0]
org.apache.kafka.common.utils.AppInfoParser - App info kafka.consumer for
consumer-kafka-supervisor-eomampef-1 unregistered
2022-07-13T19:11:05,879 ERROR [task-runner-0-priority-0]
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner - Error
while publishing segments for sequenceNumber[SequenceMetadata{sequenceId=4,
sequenceName='index_kafka_REDACT_a0e28beff1a695d_4', assignments=[],
startOffsets={1=34514359223}, exclusiveStartPartitions=[],
endOffsets={1=34517938994}, sentinel=false, checkpointed=true}]
java.util.concurrent.CancellationException: Task was cancelled.
at
com.google.common.util.concurrent.AbstractFuture.cancellationExceptionWithCause(AbstractFuture.java:392)
~[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.AbstractFuture$Sync.getValue(AbstractFuture.java:306)
~[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:286)
~[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116)
~[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.Uninterruptibles.getUninterruptibly(Uninterruptibles.java:135)
~[guava-16.0.1.jar:?]
at com.google.common.util.concurrent.Futures$4.run(Futures.java:1170)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.MoreExecutors$SameThreadExecutorService.execute(MoreExecutors.java:297)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:145)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.AbstractFuture.cancel(AbstractFuture.java:134)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.Futures$ChainingListenableFuture.cancel(Futures.java:826)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.Futures$CombinedFuture$1.run(Futures.java:1505)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.MoreExecutors$SameThreadExecutorService.execute(MoreExecutors.java:297)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:145)
[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.AbstractFuture.cancel(AbstractFuture.java:134)
[guava-16.0.1.jar:?]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner.runInternal(SeekableStreamIndexTaskRunner.java:859)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner.run(SeekableStreamIndexTaskRunner.java:265)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.seekablestream.SeekableStreamIndexTask.run(SeekableStreamIndexTask.java:149)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner$SingleTaskBackgroundRunnerCallable.call(SingleTaskBackgroundRunner.java:477)
[druid-indexing-service-0.23.0.jar:0.23.0]
at
org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner$SingleTaskBackgroundRunnerCallable.call(SingleTaskBackgroundRunner.java:449)
[druid-indexing-service-0.23.0.jar:0.23.0]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[?:1.8.0_322]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[?:1.8.0_322]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[?:1.8.0_322]
at java.lang.Thread.run(Thread.java:750) [?:1.8.0_322]
Caused by: java.util.concurrent.CancellationException: Future.cancel() was
called.
at
com.google.common.util.concurrent.AbstractFuture$Sync.complete(AbstractFuture.java:378)
~[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.AbstractFuture$Sync.cancel(AbstractFuture.java:355)
~[guava-16.0.1.jar:?]
at
com.google.common.util.concurrent.AbstractFuture.cancel(AbstractFuture.java:131)
~[guava-16.0.1.jar:?]
... 15 more
2022-07-13T19:11:05,879 WARN
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-publish]
org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver - Failed
publish (java.lang.RuntimeException: java.lang.InterruptedException)
2022-07-13T19:11:05,880 WARN
[[index_kafka_REDACT_a0e28beff1a695d_ooebmkcb]-publish]
org.apache.druid.segment.realtime.appenderator.BaseAppenderatorDriver - Failed
publish, not removing segments:
[REDACT_2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z_2022-07-13T18:05:21.125Z_24,
REDACT_2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z_2022-07-13T17:20:31.558Z_54,
REDACT_2022-07-13T16:00:00.000Z_2022-07-13T17:00:00.000Z_2022-07-13T16:03:18.415Z_65]
2022-07-13T19:11:05,880 INFO [task-runner-0-priority-0]
org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Unannouncing
segment[REDACT_2022-07-13T18:00:00.000Z_2022-07-13T19:00:00.000Z_2022-07-13T18:05:21.125Z_24]
at
path[/druid/segments/REDACTED.host.com:8100/REDACTED.host.com:8100_indexer-executor__default_tier_2022-07-13T18:06:45.560Z_b68d050f95e2471886c2569f2c7b70910]
2022-07-13T19:11:05,880 INFO [task-runner-0-priority-0]
org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Unannouncing
segment[REDACT_2022-07-13T17:00:00.000Z_2022-07-13T18:00:00.000Z_2022-07-13T17:20:31.558Z_54]
at
path[/druid/segments/REDACTED.host.com:8100/REDACTED.host.com:8100_indexer-executor__default_tier_2022-07-13T18:06:45.560Z_b68d050f95e2471886c2569f2c7b70910]
2022-07-13T19:11:05,880 INFO [task-runner-0-priority-0]
org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Unannouncing
segment[REDACT_2022-07-13T16:00:00.000Z_2022-07-13T17:00:00.000Z_2022-07-13T16:03:18.415Z_65]
at
path[/druid/segments/REDACTED.host.com:8100/REDACTED.host.com:8100_indexer-executor__default_tier_2022-07-13T18:06:45.560Z_b68d050f95e2471886c2569f2c7b70910]
2022-07-13T19:11:05,881 INFO [task-runner-0-priority-0]
org.apache.druid.curator.discovery.CuratorDruidNodeAnnouncer - Unannounced self
[{"druidNode":{"service":"druid/middleManager","host":"REDACTED.host.com","bindOnHost":false,"plaintextPort":8100,"port":-1,"tlsPort":-1,"enablePlaintextPort":true,"enableTlsPort":false},"nodeType":"peon","services":{"dataNodeService":{"type":"dataNodeService","tier":"_default_tier","maxSize":0,"type":"indexer-executor","serverType":"indexer-executor","priority":0},"lookupNodeService":{"type":"lookupNodeService","lookupTier":"__default"}}}].
2022-07-13T19:11:05,886 INFO [task-runner-0-priority-0]
org.apache.druid.indexing.worker.executor.ExecutorLifecycle - Task completed
with status: {
"id" : "index_kafka_REDACT_a0e28beff1a695d_ooebmkcb",
"status" : "SUCCESS",
"duration" : 3940816,
"errorMsg" : null,
"location" : {
"host" : null,
"port" : -1,
"tlsPort" : -1
}
}
2022-07-13T19:11:05,888 INFO [main] org.apache.druid.cli.CliPeon - Thread
[Thread[pool-3-thread-2,5,main]] is non daemon.
2022-07-13T19:11:05,888 INFO [main] org.apache.druid.cli.CliPeon - Thread
[Thread[pool-3-thread-4,5,main]] is non daemon.
2022-07-13T19:11:05,888 INFO [main] org.apache.druid.cli.CliPeon - Thread
[Thread[pool-3-thread-1,5,main]] is non daemon.
2022-07-13T19:11:05,888 INFO [main] org.apache.druid.cli.CliPeon - Thread
[Thread[pool-3-thread-3,5,main]] is non daemon.
2022-07-13T19:11:05,888 INFO [main] org.apache.druid.cli.CliPeon - Thread
[Thread[Thread-70,5,main]] is non daemon.
2022-07-13T19:11:05,888 INFO [main]
org.apache.druid.java.util.common.lifecycle.Lifecycle - Lifecycle [module]
already stopped and stop was called. Silently skipping
Cannot remove shutdown hook, already shutting down!
Finished peon task
```
These are INFO level logs, I will probably have to run debug mode again to
get more data and also try out the flame graphs for peons (as recommended
earlier) to get a better idea of what's going on. But just wanted to provide an
update about the 0.23.0 upgrade and confirming this specific issue persists.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
