Kafka indexing service task show Task completed with status success but status show failed

Hi,
I have a task in log show success but in task’s status show failed.

I also attached the full log.

Please tell me what was happening?

Regards,

Chanh

{

“task”: “index_kafka_ad_statistics_hourly_1383441b2e964a7_efpcpdia”,

“status”: {

“id”: “index_kafka_ad_statistics_hourly_1383441b2e964a7_efpcpdia”,

“status”: “FAILED”,

“duration”: -1

}

}

``

brief task log

Total time for which application threads were stopped: 0.0003114 seconds, Stopping threads took: 0.0000477 seconds

2016-10-18T13:59:34,318 INFO [task-runner-0-priority-0] io.druid.indexing.worker.executor.ExecutorLifecycle - Task completed with status: {

** “id” : “index_kafka_ad_statistics_hourly_1383441b2e964a7_efpcpdia”,**

** “status” : “SUCCESS”,**

** “duration” : 531438**

}

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.649: ThreadDump [ 196 0 0 ] [ 0 0 0 0 2 ] 0

Total time for which application threads were stopped: 0.0024846 seconds, Stopping threads took: 0.0000486 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.658: BulkRevokeBias [ 196 0 0 ] [ 0 0 0 0 1 ] 0

Total time for which application threads were stopped: 0.0019829 seconds, Stopping threads took: 0.0000438 seconds

2016-10-18T13:59:34,335 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.server.coordination.AbstractDataSegmentAnnouncer.stop()] on object[io.druid.server.coordination.BatchDataSegmentAnnouncer@68bd8ca7].

2016-10-18T13:59:34,335 INFO [main] io.druid.server.coordination.AbstractDataSegmentAnnouncer - Stopping class io.druid.server.coordination.BatchDataSegmentAnnouncer with config[io.druid.server.initialization.ZkPathsConfig@20876eed]

2016-10-18T13:59:34,335 INFO [main] io.druid.curator.announcement.Announcer - unannouncing [/druid/prod/announcements/hostname-20:8112]

2016-10-18T13:59:34,353 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.server.listener.announcer.ListenerResourceAnnouncer.stop()] on object[io.druid.query.lookup.LookupResourceListenerAnnouncer@35f7969d].

2016-10-18T13:59:34,353 INFO [main] io.druid.curator.announcement.Announcer - unannouncing [/druid/prod/listeners/lookups/__default/hostname-20:8112]

2016-10-18T13:59:34,356 INFO [main] io.druid.server.listener.announcer.ListenerResourceAnnouncer - Unannouncing start time on [/druid/prod/listeners/lookups/__default/hostname-20:8112]

2016-10-18T13:59:34,356 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.query.lookup.LookupReferencesManager.stop()] on object[io.druid.query.lookup.LookupReferencesManager@3b57dba4].

2016-10-18T13:59:34,356 INFO [main] io.druid.query.lookup.LookupReferencesManager - Stopping lookup factory references manager

2016-10-18T13:59:34,360 INFO [main] org.eclipse.jetty.server.ServerConnector - Stopped ServerConnector@5bec3e0{HTTP/1.1}{0.0.0.0:8112}

2016-10-18T13:59:34,362 INFO [main] org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@634e1b39{/,null,UNAVAILABLE}

2016-10-18T13:59:34,364 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.indexing.worker.executor.ExecutorLifecycle.stop() throws java.lang.Exception] on object[io.druid.indexing.worker.executor.ExecutorLifecycle@5ed5b321].

2016-10-18T13:59:34,364 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.indexing.overlord.ThreadPoolTaskRunner.stop()] on object[io.druid.indexing.overlord.ThreadPoolTaskRunner@514377fc].

2016-10-18T13:59:34,365 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.curator.discovery.ServerDiscoverySelector.stop() throws java.io.IOException] on object[io.druid.curator.discovery.ServerDiscoverySelector@5f726750].

2016-10-18T13:59:34,368 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.curator.announcement.Announcer.stop()] on object[io.druid.curator.announcement.Announcer@2b6c7012].

2016-10-18T13:59:34,369 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.curator.discovery.ServerDiscoverySelector.stop() throws java.io.IOException] on object[io.druid.curator.discovery.ServerDiscoverySelector@2b80e5a9].

2016-10-18T13:59:34,369 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.http.client.NettyHttpClient.stop()] on object[com.metamx.http.client.NettyHttpClient@23ca36d].

2016-10-18T13:59:34,383 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.storage.hdfs.HdfsStorageAuthentication.stop()] on object[io.druid.storage.hdfs.HdfsStorageAuthentication@69364b2d].

2016-10-18T13:59:34,383 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.metrics.MonitorScheduler.stop()] on object[com.metamx.metrics.MonitorScheduler@7bee8621].

2016-10-18T13:59:34,384 INFO [main] io.druid.curator.CuratorModule - Stopping Curator

2016-10-18T13:59:34,385 INFO [Curator-Framework-0] org.apache.curator.framework.imps.CuratorFrameworkImpl - backgroundOperationsLoop exiting

2016-10-18T13:59:34,392 INFO [main] org.apache.zookeeper.ZooKeeper - Session: 0x257d3783b2e0038 closed

2016-10-18T13:59:34,392 INFO [main-EventThread] org.apache.zookeeper.ClientCnxn - EventThread shut down for session: 0x257d3783b2e0038

2016-10-18T13:59:34,392 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.emitter.service.ServiceEmitter.close() throws java.io.IOException] on object[com.metamx.emitter.service.ServiceEmitter@570ba13].

2016-10-18T13:59:34,392 INFO [main] com.metamx.emitter.core.LoggingEmitter - Close: started [false]

2016-10-18T13:59:34,392 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner.stop()] on object[io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner@27dc627a].

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.725: RevokeBias [ 29 1 1 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0001849 seconds, Stopping threads took: 0.0000731 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.726: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000555 seconds, Stopping threads took: 0.0000089 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.726: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000443 seconds, Stopping threads took: 0.0000056 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.726: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000422 seconds, Stopping threads took: 0.0000054 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.726: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000482 seconds, Stopping threads took: 0.0000074 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.726: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000436 seconds, Stopping threads took: 0.0000054 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.726: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000444 seconds, Stopping threads took: 0.0000056 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.726: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000498 seconds, Stopping threads took: 0.0000056 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.726: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000468 seconds, Stopping threads took: 0.0000063 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.726: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000470 seconds, Stopping threads took: 0.0000086 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.726: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000477 seconds, Stopping threads took: 0.0000088 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.727: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000464 seconds, Stopping threads took: 0.0000087 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.727: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000526 seconds, Stopping threads took: 0.0000115 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.727: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000540 seconds, Stopping threads took: 0.0000087 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.727: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000532 seconds, Stopping threads took: 0.0000120 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.727: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000472 seconds, Stopping threads took: 0.0000087 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.727: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000540 seconds, Stopping threads took: 0.0000121 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.727: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000486 seconds, Stopping threads took: 0.0000089 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.727: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000467 seconds, Stopping threads took: 0.0000087 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.727: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000542 seconds, Stopping threads took: 0.0000122 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.727: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000469 seconds, Stopping threads took: 0.0000084 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.727: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000455 seconds, Stopping threads took: 0.0000088 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.728: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000537 seconds, Stopping threads took: 0.0000093 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.728: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000476 seconds, Stopping threads took: 0.0000098 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.728: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000506 seconds, Stopping threads took: 0.0000135 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.729: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000584 seconds, Stopping threads took: 0.0000102 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.730: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000497 seconds, Stopping threads took: 0.0000084 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.730: BulkRevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0001276 seconds, Stopping threads took: 0.0000204 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.730: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000526 seconds, Stopping threads took: 0.0000078 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.730: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000496 seconds, Stopping threads took: 0.0000070 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.731: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000484 seconds, Stopping threads took: 0.0000071 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.731: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000535 seconds, Stopping threads took: 0.0000104 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.732: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000630 seconds, Stopping threads took: 0.0000115 seconds

2016-10-18 13:59:34,432 Thread-2 ERROR Unable to register shutdown hook because JVM is shutting down. java.lang.IllegalStateException: Not started

at io.druid.common.config.Log4jShutdown.addShutdownCallback(Log4jShutdown.java:45)

at org.apache.logging.log4j.core.impl.Log4jContextFactory.addShutdownCallback(Log4jContextFactory.java:273)

at org.apache.logging.log4j.core.LoggerContext.setUpShutdownHook(LoggerContext.java:256)

at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:216)

at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:145)

at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:41)

at org.apache.logging.log4j.LogManager.getContext(LogManager.java:182)

at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:103)

at org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:43)

at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:42)

at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:29)

at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:284)

at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:155)

at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:132)

at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:273)

at org.apache.hadoop.hdfs.LeaseRenewer.(LeaseRenewer.java:72)

at org.apache.hadoop.hdfs.DFSClient.getLeaseRenewer(DFSClient.java:699)

at org.apache.hadoop.hdfs.DFSClient.close(DFSClient.java:859)

at org.apache.hadoop.hdfs.DistributedFileSystem.close(DistributedFileSystem.java:853)

at org.apache.hadoop.fs.FileSystem$Cache.closeAll(FileSystem.java:2407)

at org.apache.hadoop.fs.FileSystem$Cache$ClientFinalizer.run(FileSystem.java:2424)

at org.apache.hadoop.util.ShutdownHookManager$1.run(ShutdownHookManager.java:54)

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.765: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0001445 seconds, Stopping threads took: 0.0000269 seconds

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.766: RevokeBias [ 28 0 0 ] [ 0 0 0 0 0 ] 0

Total time for which application threads were stopped: 0.0000636 seconds, Stopping threads took: 0.0000134 seconds

Heap

par new generation total 943744K, used 662002K [0x0000000680000000, 0x00000006c0000000, 0x00000006c0000000)

eden space 838912K, 74% used [0x0000000680000000, 0x00000006a650d620, 0x00000006b3340000)

from space 104832K, 32% used [0x00000006b99a0000, 0x00000006bbb0f408, 0x00000006c0000000)

to space 104832K, 0% used [0x00000006b3340000, 0x00000006b3340000, 0x00000006b99a0000)

concurrent mark-sweep generation total 4194304K, used 0K [0x00000006c0000000, 0x00000007c0000000, 0x00000007c0000000)

Metaspace used 49898K, capacity 50520K, committed 51072K, reserved 1093632K

class space used 6444K, capacity 6577K, committed 6704K, reserved 1048576K

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count

556.766: no vm operation [ 26 1 1 ] [ 0 0 0 0 312 ] 0

Polling page always armed

ThreadDump 1

ForceSafepoint 1

Deoptimize 32

CollectForMetadataAllocation 30

GenCollectForAllocation 1

CMS_Initial_Mark 1

CMS_Final_Remark 1

EnableBiasedLocking 1

RevokeBias 236

BulkRevokeBias 10

10 VM operations coalesced during safepoint

Maximum sync time 901 ms

Maximum vm operation time (except for Exit VM operation) 865 ms

``

log.txt (410 KB)

That’s odd. Is there anything interesting in your middle manager or overlord logs?