Compaction task failed, how can I troubleshoot?
- Dominant language
- Java
- Stars
- 14.1k
- Forks
- 3.8k
- Avg merge
- 2d 58m
- Merged PRs (30d)
- 233
Description
Hi experts,
I am using druid 0.22.1, and I want to compact some small segments, so I submit a compaction task:
```
{
"type": "compact",
"dataSource": "autotest",
"ioConfig": {
"type": "compact",
"inputSpec": {
"type": "interval",
"interval": "1970-01-01T00:00:00Z/2023-11-18T07:14:34.000Z"
},
"dropExisting": true
},
"granularitySpec": {
"segmentGranularity": "MINUTE",
"queryGranularity": "MINUTE"
}
}
```
But the compaction task failed with the following status information
```
{
"id": "compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z",
"groupId": "compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z",
"type": "compact",
"createdTime": "2022-11-18T08:41:49.908Z",
"queueInsertionTime": "1970-01-01T00:00:00.000Z",
"statusCode": "FAILED",
"status": "FAILED",
"runnerStatusCode": "WAITING",
"duration": 27628,
"location": {
"host": "172.24.131.32",
"port": -1,
"tlsPort": 8100
},
"dataSource": "autotest",
"errorMsg": "Ran [1] specs, [0] succeeded, [1] failed"
}
```
And the logs:
```
{"instant":{"epochSecond":1668760935,"nanoOfSecond":19000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.storage.s3.S3DataSegmentPuller","message":"Pulling index at path[CloudObjectLocation{bucket='cerberus-zontal-ingest', path='druid/segments/autotest/2022-11-18T07:12:33.000Z_2022-11-18T07:12:34.000Z/2022-11-18T07:12:34.855Z/0/index.zip'}] to outDir[var/druid/task/compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z/work/autotest/2022-11-18T07:12:33.000Z_2022-11-18T07:12:34.000Z/2022-11-18T07:12:34.855Z/0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760935,"nanoOfSecond":217000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.storage.s3.S3DataSegmentPuller","message":"Loaded 370186 bytes from [CloudObjectLocation{bucket='cerberus-zontal-ingest', path='druid/segments/autotest/2022-11-18T07:12:33.000Z_2022-11-18T07:12:34.000Z/2022-11-18T07:12:34.855Z/0/index.zip'}] to [/opt/druid/var/druid/task/compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z/work/autotest/2022-11-18T07:12:33.000Z_2022-11-18T07:12:34.000Z/2022-11-18T07:12:34.855Z/0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760935,"nanoOfSecond":218000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.storage.s3.S3DataSegmentPuller","message":"Pulling index at path[CloudObjectLocation{bucket='cerberus-zontal-ingest', path='druid/segments/autotest/2022-11-18T07:12:41.000Z_2022-11-18T07:12:42.000Z/2022-11-18T07:12:42.687Z/0/index.zip'}] to outDir[var/druid/task/compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z/work/autotest/2022-11-18T07:12:41.000Z_2022-11-18T07:12:42.000Z/2022-11-18T07:12:42.687Z/0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760935,"nanoOfSecond":318000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.storage.s3.S3DataSegmentPuller","message":"Loaded 370186 bytes from [CloudObjectLocation{bucket='cerberus-zontal-ingest', path='druid/segments/autotest/2022-11-18T07:12:41.000Z_2022-11-18T07:12:42.000Z/2022-11-18T07:12:42.687Z/0/index.zip'}] to [/opt/druid/var/druid/task/compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z/work/autotest/2022-11-18T07:12:41.000Z_2022-11-18T07:12:42.000Z/2022-11-18T07:12:42.687Z/0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760935,"nanoOfSecond":319000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.storage.s3.S3DataSegmentPuller","message":"Pulling index at path[CloudObjectLocation{bucket='cerberus-zontal-ingest', path='druid/segments/autotest/2022-11-18T07:13:34.000Z_2022-11-18T07:13:35.000Z/2022-11-18T07:13:36.349Z/0/index.zip'}] to outDir[var/druid/task/compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z/work/autotest/2022-11-18T07:13:34.000Z_2022-11-18T07:13:35.000Z/2022-11-18T07:13:36.349Z/0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760935,"nanoOfSecond":414000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.storage.s3.S3DataSegmentPuller","message":"Loaded 370186 bytes from [CloudObjectLocation{bucket='cerberus-zontal-ingest', path='druid/segments/autotest/2022-11-18T07:13:34.000Z_2022-11-18T07:13:35.000Z/2022-11-18T07:13:36.349Z/0/index.zip'}] to [/opt/druid/var/druid/task/compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z/work/autotest/2022-11-18T07:13:34.000Z_2022-11-18T07:13:35.000Z/2022-11-18T07:13:36.349Z/0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760935,"nanoOfSecond":816000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.indexing.common.task.CompactionTask","message":"Generate compaction task spec with new query granularity overrided from input [{type=period, period=PT1M, timeZone=UTC, origin=null}]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":502000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.indexing.common.task.CompactionTask","message":"Generated [1] compaction task specs","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":617000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.indexing.common.task.AbstractBatchIndexTask","message":"[forceTimeChunkLock] is set to true in task context. Use timeChunk lock","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":703000000},"thread":"task-runner-0-priority-0","level":"WARN","loggerName":"org.apache.druid.indexing.common.task.CompactionTask","message":"indexSpec is not ready: [{\n \"type\" : \"index_parallel\",\n \"id\" : \"compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z\",\n \"groupId\" : \"compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z\",\n \"resource\" : {\n \"availabilityGroup\" : \"compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z\",\n \"requiredCapacity\" : 1\n },\n \"spec\" : {\n \"dataSchema\" : {\n \"dataSource\" : \"autotest\",\n \"timestampSpec\" : {\n \"column\" : \"__time\",\n \"format\" : \"millis\",\n \"missingValue\" : null\n },\n \"dimensionsSpec\" : {\n \"dimensions\" : [ {\n \"type\" : \"string\",\n \"name\" : \"content_identifier\",\n \"multiValueHandling\" : \"SORTED_ARRAY\",\n \"createBitmapIndex\" : true\n }, {\n \"type\" : \"string\",\n \"name\" : \"information_package_iri\",\n \"multiValueHandling\" : \"SORTED_ARRAY\",\n \"createBitmapIndex\" : true\n }, {\n \"type\" : \"string\",\n \"name\" : \"iri\",\n \"multiValueHandling\" : \"SORTED_ARRAY\",\n \"createBitmapIndex\" : true\n }, {\n \"type\" : \"long\",\n \"name\" : \"x1_value_int\",\n \"multiValueHandling\" : \"SORTED_ARRAY\",\n \"createBitmapIndex\" : false\n }, {\n \"type\" : \"long\",\n \"name\" : \"y1_value_int\",\n \"multiValueHandling\" : \"SORTED_ARRAY\",\n \"createBitmapIndex\" : false\n } ],\n \"dimensionExclusions\" : [ \"__time\" ]\n },\n \"metricsSpec\" : [ ],\n \"granularitySpec\" : {\n \"type\" : \"uniform\",\n \"segmentGranularity\" : \"MINUTE\",\n \"queryGranularity\" : \"MINUTE\",\n \"rollup\" : false,\n \"intervals\" : [ \"2022-11-17T07:51:00.000Z/2022-11-18T07:13:35.000Z\" ]\n },\n \"transformSpec\" : {\n \"filter\" : null,\n \"transforms\" : [ ]\n }\n },\n \"ioConfig\" : {\n \"type\" : \"index_parallel\",\n \"inputSource\" : {\n \"type\" : \"druid\",\n \"dataSource\" : \"autotest\",\n \"interval\" : \"1970-01-01T00:00:00.000Z/2022-11-18T07:14:34.000Z\"\n },\n \"inputFormat\" : null,\n \"appendToExisting\" : false,\n \"dropExisting\" : true\n },\n \"tuningConfig\" : {\n \"type\" : \"compaction\",\n \"maxRowsPerSegment\" : 5000000,\n \"appendableIndexSpec\" : {\n \"type\" : \"onheap\"\n },\n \"maxRowsInMemory\" : 1000000,\n \"maxBytesInMemory\" : 0,\n \"skipBytesInMemoryOverheadCheck\" : false,\n \"maxTotalRows\" : 9223372036854775807,\n \"numShards\" : null,\n \"splitHintSpec\" : null,\n \"partitionsSpec\" : {\n \"type\" : \"dynamic\",\n \"maxRowsPerSegment\" : 5000000,\n \"maxTotalRows\" : 9223372036854775807\n },\n \"indexSpec\" : {\n \"bitmap\" : {\n \"type\" : \"roaring\",\n \"compressRunOnSerialization\" : true\n },\n \"dimensionCompression\" : \"lz4\",\n \"metricCompression\" : \"lz4\",\n \"longEncoding\" : \"longs\",\n \"segmentLoader\" : null\n },\n \"indexSpecForIntermediatePersists\" : {\n \"bitmap\" : {\n \"type\" : \"roaring\",\n \"compressRunOnSerialization\" : true\n },\n \"dimensionCompression\" : \"lz4\",\n \"metricCompression\" : \"lz4\",\n \"longEncoding\" : \"longs\",\n \"segmentLoader\" : null\n },\n \"maxPendingPersists\" : 0,\n \"forceGuaranteedRollup\" : false,\n \"reportParseExceptions\" : false,\n \"pushTimeout\" : 0,\n \"segmentWriteOutMediumFactory\" : null,\n \"maxNumConcurrentSubTasks\" : 1,\n \"maxRetry\" : 3,\n \"taskStatusCheckPeriodMs\" : 1000,\n \"chatHandlerTimeout\" : \"PT10S\",\n \"chatHandlerNumRetries\" : 5,\n \"maxNumSegmentsToMerge\" : 100,\n \"totalNumMergeTasks\" : 10,\n \"logParseExceptions\" : false,\n \"maxParseExceptions\" : 2147483647,\n \"maxSavedParseExceptions\" : 0,\n \"maxColumnsToMerge\" : -1,\n \"awaitSegmentAvailabilityTimeoutMillis\" : 0,\n \"partitionDimensions\" : [ ]\n }\n },\n \"context\" : {\n \"useLineageBasedSegmentAllocation\" : true,\n \"appenderatorTrackingTaskId\" : \"compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z\",\n \"storeCompactionState\" : true,\n \"forceTimeChunkLock\" : true,\n \"priority\" : 25\n },\n \"dataSource\" : \"autotest\"\n}].\nTrying the next indexSpec.","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":703000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.indexing.common.task.CompactionTask","message":"Ran [1] specs, [0] succeeded, [1] failed","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":705000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.indexing.worker.executor.ExecutorLifecycle","message":"Task completed with status: {\n \"id\" : \"compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z\",\n \"status\" : \"FAILED\",\n \"duration\" : 6798,\n \"errorMsg\" : \"Ran [1] specs, [0] succeeded, [1] failed\",\n \"location\" : {\n \"host\" : null,\n \"port\" : -1,\n \"tlsPort\" : -1\n }\n}","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":710000000},"thread":"main","level":"INFO","loggerName":"org.apache.druid.java.util.common.lifecycle.Lifecycle","message":"Stopping lifecycle [module] stage [ANNOUNCEMENTS]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":711000000},"thread":"main","level":"INFO","loggerName":"org.apache.druid.java.util.common.lifecycle.Lifecycle","message":"Stopping lifecycle [module] stage [SERVER]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":716000000},"thread":"main","level":"INFO","loggerName":"org.eclipse.jetty.server.AbstractConnector","message":"Stopped ServerConnector@58bad46f{SSL, (ssl, http/1.1)}{0.0.0.0:8100}","endOfBatch":false,"loggerFqcn":"org.eclipse.jetty.util.log.Slf4jLog","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":717000000},"thread":"main","level":"INFO","loggerName":"org.eclipse.jetty.server.session","message":"node0 Stopped scavenging","endOfBatch":false,"loggerFqcn":"org.eclipse.jetty.util.log.Slf4jLog","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":802000000},"thread":"main","level":"INFO","loggerName":"org.eclipse.jetty.server.handler.ContextHandler","message":"Stopped o.e.j.s.ServletContextHandler@7c4ca87c{/,null,STOPPED}","endOfBatch":false,"loggerFqcn":"org.eclipse.jetty.util.log.Slf4jLog","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":805000000},"thread":"main","level":"INFO","loggerName":"org.apache.druid.java.util.common.lifecycle.Lifecycle","message":"Stopping lifecycle [module] stage [NORMAL]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":806000000},"thread":"main","level":"INFO","loggerName":"org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner","message":"Starting graceful shutdown of task[compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z].","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":816000000},"thread":"LookupExtractorFactoryContainerProvider-MainThread","level":"INFO","loggerName":"org.apache.druid.query.lookup.LookupReferencesManager","message":"Lookup Management loop exited. Lookup notices are not handled anymore.","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":103,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":816000000},"thread":"main","level":"INFO","loggerName":"org.apache.druid.query.lookup.LookupReferencesManager","message":"Closed lookup [deleted_information_packages].","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":821000000},"thread":"Curator-Framework-0","level":"INFO","loggerName":"org.apache.curator.framework.imps.CuratorFrameworkImpl","message":"backgroundOperationsLoop exiting","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":99,"threadPriority":5}
{"instant":{"epochSecond":1668760937,"nanoOfSecond":18000000},"thread":"main","level":"INFO","loggerName":"org.apache.zookeeper.ZooKeeper","message":"Session: 0x1001892b7e9010b closed","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760937,"nanoOfSecond":18000000},"thread":"main-EventThread","level":"INFO","loggerName":"org.apache.zookeeper.ClientCnxn","message":"EventThread shut down for session: 0x1001892b7e9010b","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":98,"threadPriority":5}
{"instant":{"epochSecond":1668760937,"nanoOfSecond":105000000},"thread":"main","level":"INFO","loggerName":"org.apache.druid.java.util.common.lifecycle.Lifecycle","message":"Stopping lifecycle [module] stage [INIT]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5}
Finished peon task
```
I notice there is a "indexSpec is not ready:" warning in the log, but I don't know what does this mean.
FYI: The datasource is "Fully available"
Can anyone help me? Or how can I troubleshout issues like this? Thanks a lot in advance.
Contributor guide
Research direction
Start with the submitted compaction-task JSON and the CompactionTask, S3DataSegmentPuller, and ExecutorLifecycle log entries. Trace why the single generated compaction spec fails beyond the reported summary. Done means the failure has an identified, reproducible cause and the issue contains actionable troubleshooting guidance or a confirmed fix.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- java
- Domain
- databases
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100