You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@druid.apache.org by GitBox <gi...@apache.org> on 2019/12/23 23:13:23 UTC
[GitHub] [druid] pdeva edited a comment on issue #9040: KIS tasks out of
sync for no reason at all
pdeva edited a comment on issue #9040: KIS tasks out of sync for no reason at all
URL: https://github.com/apache/druid/issues/9040#issuecomment-568602033
so this seems to be happening with every single data source.
that particular kafka topic is consumed by multiple druid data sources.
so to keep things simple i picked a topic which has only a single corresponding druid data source .
here are the logs (exact same as above) for `apm-span-stats` topic:
The corresponding druid data source `apm-span-second` for it shows the tasks themselves completing successfully:
Logs regarding offset for `apm-span-stats` topic from druid coordinator:
Here are the logs from one of the completed tasks for this data source:
```
2019-12-23T21:05:53,710 INFO [coordinator_handoff_scheduled_0] org.apache.druid.segment.realtime.appenderator.StreamAppenderatorDriver - Segment[apm-span-second_2019-12-23T17:00:00.000Z_2019-12-23T18:00:00.000Z_2019-12-23T17:00:00.157Z_1] successfully handed off, dropping.
2019-12-23T21:05:53,711 INFO [appenderator_persist_0] org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Unannouncing segment[apm-span-second_2019-12-23T19:00:00.000Z_2019-12-23T20:00:00.000Z_2019-12-23T19:00:01.353Z] at path[/druidprod/base/segments/192.168.51.36:8119/192.168.51.36:8119_indexer-executor__default_tier_2019-12-23T17:03:54.490Z_acd4a8c7e5e44a2aaf65bbb14d9153d30]
2019-12-23T21:05:53,711 INFO [appenderator_persist_0] org.apache.druid.segment.realtime.appenderator.AppenderatorImpl - Deleting Index File[/tmp/persistent/task/index_kafka_apm-span-second_28bbb49e5a89ee5_encagppk/work/persist/apm-span-second_2019-12-23T19:00:00.000Z_2019-12-23T20:00:00.000Z_2019-12-23T19:00:01.353Z]
2019-12-23T21:05:53,714 INFO [appenderator_persist_0] org.apache.druid.segment.realtime.appenderator.AppenderatorImpl - Removing sink for segment[apm-span-second_2019-12-23T20:00:00.000Z_2019-12-23T21:00:00.000Z_2019-12-23T20:00:00.171Z].
2019-12-23T21:05:53,714 INFO [appenderator_persist_0] org.apache.druid.segment.realtime.appenderator.AppenderatorImpl - Removing commit metadata for segment[apm-span-second_2019-12-23T20:00:00.000Z_2019-12-23T21:00:00.000Z_2019-12-23T20:00:00.171Z].
2019-12-23T21:05:53,715 INFO [appenderator_persist_0] org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Unannouncing segment[apm-span-second_2019-12-23T20:00:00.000Z_2019-12-23T21:00:00.000Z_2019-12-23T20:00:00.171Z] at path[/druidprod/base/segments/192.168.51.36:8119/192.168.51.36:8119_indexer-executor__default_tier_2019-12-23T17:03:54.490Z_acd4a8c7e5e44a2aaf65bbb14d9153d30]
2019-12-23T21:05:53,715 INFO [appenderator_persist_0] org.apache.druid.segment.realtime.appenderator.AppenderatorImpl - Deleting Index File[/tmp/persistent/task/index_kafka_apm-span-second_28bbb49e5a89ee5_encagppk/work/persist/apm-span-second_2019-12-23T20:00:00.000Z_2019-12-23T21:00:00.000Z_2019-12-23T20:00:00.171Z]
2019-12-23T21:05:53,718 INFO [appenderator_persist_0] org.apache.druid.segment.realtime.appenderator.AppenderatorImpl - Removing sink for segment[apm-span-second_2019-12-23T17:00:00.000Z_2019-12-23T18:00:00.000Z_2019-12-23T17:00:00.157Z_1].
2019-12-23T21:05:53,718 INFO [appenderator_persist_0] org.apache.druid.segment.realtime.appenderator.AppenderatorImpl - Removing commit metadata for segment[apm-span-second_2019-12-23T17:00:00.000Z_2019-12-23T18:00:00.000Z_2019-12-23T17:00:00.157Z_1].
2019-12-23T21:05:53,719 INFO [appenderator_persist_0] org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Unannouncing segment[apm-span-second_2019-12-23T17:00:00.000Z_2019-12-23T18:00:00.000Z_2019-12-23T17:00:00.157Z_1] at path[/druidprod/base/segments/192.168.51.36:8119/192.168.51.36:8119_indexer-executor__default_tier_2019-12-23T17:03:54.490Z_acd4a8c7e5e44a2aaf65bbb14d9153d30]
2019-12-23T21:05:53,719 INFO [appenderator_persist_0] org.apache.druid.curator.announcement.Announcer - unannouncing [/druidprod/base/segments/192.168.51.36:8119/192.168.51.36:8119_indexer-executor__default_tier_2019-12-23T17:03:54.490Z_acd4a8c7e5e44a2aaf65bbb14d9153d30]
2019-12-23T21:05:53,734 INFO [appenderator_persist_0] org.apache.druid.segment.realtime.appenderator.AppenderatorImpl - Deleting Index File[/tmp/persistent/task/index_kafka_apm-span-second_28bbb49e5a89ee5_encagppk/work/persist/apm-span-second_2019-12-23T17:00:00.000Z_2019-12-23T18:00:00.000Z_2019-12-23T17:00:00.157Z_1]
2019-12-23T21:05:53,736 INFO [appenderator_persist_0] org.apache.druid.segment.realtime.appenderator.StreamAppenderatorDriver - Successfully handed off [5] segments.
2019-12-23T21:05:53,737 INFO [task-runner-0-priority-0] org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner - Handoff completed for segments [apm-span-second_2019-12-23T18:00:00.000Z_2019-12-23T19:00:00.000Z_2019-12-23T18:00:01.127Z, apm-span-second_2019-12-23T19:00:00.000Z_2019-12-23T20:00:00.000Z_2019-12-23T19:00:01.353Z, apm-span-second_2019-12-23T20:00:00.000Z_2019-12-23T21:00:00.000Z_2019-12-23T20:00:00.171Z, apm-span-second_2019-12-23T21:00:00.000Z_2019-12-23T22:00:00.000Z_2019-12-23T21:00:00.154Z, apm-span-second_2019-12-23T17:00:00.000Z_2019-12-23T18:00:00.000Z_2019-12-23T17:00:00.157Z_1] with metadata[{nextPartitions=SeekableStreamStartSequenceNumbers{stream='apm-span-stats', partitionSequenceNumberMap={0=27665649}, exclusivePartitions=[]}, publishPartitions=SeekableStreamEndSequenceNumbers{stream='apm-span-stats', partitionSequenceNumberMap={0=27665649}}}].
2019-12-23T21:05:53,737 INFO [task-runner-0-priority-0] org.apache.druid.segment.realtime.appenderator.AppenderatorImpl - Shutting down...
2019-12-23T21:05:53,741 INFO [task-runner-0-priority-0] org.apache.druid.segment.realtime.firehose.ServiceAnnouncingChatHandlerProvider - Unregistering chat handler[index_kafka_apm-span-second_28bbb49e5a89ee5_encagppk]
2019-12-23T21:05:53,741 INFO [task-runner-0-priority-0] org.apache.druid.curator.discovery.CuratorDruidNodeAnnouncer - Unannouncing [DiscoveryDruidNode{druidNode=DruidNode{serviceName='middlemanager', host='192.168.51.36', bindOnHost=false, port=-1, plaintextPort=8119, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}, nodeType='PEON', services={dataNodeService=DataNodeService{tier='_default_tier', maxSize=0, type=indexer-executor, priority=0}, lookupNodeService=LookupNodeService{lookupTier='__default'}}}].
2019-12-23T21:05:53,741 INFO [task-runner-0-priority-0] org.apache.druid.curator.announcement.Announcer - unannouncing [/druidprod/base/internal-discovery/PEON/192.168.51.36:8119]
2019-12-23T21:05:53,749 INFO [task-runner-0-priority-0] org.apache.druid.curator.discovery.CuratorDruidNodeAnnouncer - Unannounced [DiscoveryDruidNode{druidNode=DruidNode{serviceName='middlemanager', host='192.168.51.36', bindOnHost=false, port=-1, plaintextPort=8119, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}, nodeType='PEON', services={dataNodeService=DataNodeService{tier='_default_tier', maxSize=0, type=indexer-executor, priority=0}, lookupNodeService=LookupNodeService{lookupTier='__default'}}}].
2019-12-23T21:05:53,749 INFO [task-runner-0-priority-0] org.apache.druid.curator.announcement.Announcer - unannouncing [/druidprod/base/announcements/192.168.51.36:8119]
2019-12-23T21:05:53,761 INFO [task-runner-0-priority-0] org.apache.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_apm-span-second_28bbb49e5a89ee5_encagppk] status changed to [SUCCESS].
2019-12-23T21:05:53,763 INFO [task-runner-0-priority-0] org.apache.druid.indexing.worker.executor.ExecutorLifecycle - Task completed with status: {
"id" : "index_kafka_apm-span-second_28bbb49e5a89ee5_encagppk",
"status" : "SUCCESS",
"duration" : 14520549,
"errorMsg" : null,
"location" : {
"host" : null,
"port" : -1,
"tlsPort" : -1
}
}
2019-12-23T21:05:53,770 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle [module] stage [ANNOUNCEMENTS]
2019-12-23T21:05:53,771 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.curator.announcement.Announcer.stop()] on object[org.apache.druid.curator.announcement.Announcer@120411ec].
2019-12-23T21:05:53,772 INFO [main] org.apache.druid.curator.announcement.Announcer - Stopping announcer
2019-12-23T21:05:53,772 INFO [main] org.apache.druid.curator.announcement.Announcer - unannouncing [/druidprod/base/listeners/lookups/__default/http:192.168.51.36:8119]
2019-12-23T21:05:53,777 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle [module] stage [SERVER]
2019-12-23T21:05:53,777 INFO [main] org.apache.druid.server.initialization.jetty.JettyServerModule - Stopping Jetty Server...
2019-12-23T21:05:53,782 INFO [main] org.eclipse.jetty.server.AbstractConnector - Stopped ServerConnector@59f3426f{HTTP/1.1,[http/1.1]}{0.0.0.0:8119}
2019-12-23T21:05:53,782 INFO [main] org.eclipse.jetty.server.session - node0 Stopped scavenging
2019-12-23T21:05:53,783 INFO [main] org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@7221539{/,null,UNAVAILABLE}
2019-12-23T21:05:53,785 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle [module] stage [NORMAL]
2019-12-23T21:05:53,786 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.server.listener.announcer.ListenerResourceAnnouncer.stop()] on object[org.apache.druid.query.lookup.LookupResourceListenerAnnouncer@6c995c5d].
2019-12-23T21:05:53,786 INFO [main] org.apache.druid.server.listener.announcer.ListenerResourceAnnouncer - Unannouncing start time on [/druidprod/base/listeners/lookups/__default/http:192.168.51.36:8119]
2019-12-23T21:05:53,786 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.indexing.worker.executor.ExecutorLifecycle.stop() throws java.lang.Exception] on object[org.apache.druid.indexing.worker.executor.ExecutorLifecycle@19eea77c].
2019-12-23T21:05:53,786 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner.stop()] on object[org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner@11e17893].
2019-12-23T21:05:53,786 INFO [main] org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner - Starting graceful shutdown of task[index_kafka_apm-span-second_28bbb49e5a89ee5_encagppk].
2019-12-23T21:05:53,786 INFO [main] org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner - Stopping gracefully (status: [PUBLISHING])
2019-12-23T21:05:53,786 INFO [main] org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner - Graceful shutdown of task[index_kafka_apm-span-second_28bbb49e5a89ee5_encagppk] finished in 0ms.
2019-12-23T21:05:53,786 INFO [main] org.apache.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_apm-span-second_28bbb49e5a89ee5_encagppk] status changed to [SUCCESS].
2019-12-23T21:05:53,787 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.indexing.worker.IntermediaryDataManager.stop() throws java.lang.InterruptedException] on object[org.apache.druid.indexing.worker.IntermediaryDataManager@50f4b83d].
2019-12-23T21:05:53,787 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.client.cache.RedisCache.close()] on object[org.apache.druid.client.cache.RedisCache@9f2376f].
2019-12-23T21:05:53,787 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.discovery.DruidLeaderClient.stop()] on object[org.apache.druid.discovery.DruidLeaderClient@56c0a61e].
2019-12-23T21:05:53,787 INFO [main] org.apache.druid.discovery.DruidLeaderClient - Stopped.
2019-12-23T21:05:53,787 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.curator.discovery.ServerDiscoverySelector.stop() throws java.io.IOException] on object[org.apache.druid.curator.discovery.ServerDiscoverySelector@76d0ecd7].
2019-12-23T21:05:53,789 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.java.util.metrics.MonitorScheduler.stop()] on object[org.apache.druid.java.util.metrics.MonitorScheduler@36551e97].
2019-12-23T21:05:53,789 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.query.lookup.LookupReferencesManager.stop()] on object[org.apache.druid.query.lookup.LookupReferencesManager@27ffd9f8].
2019-12-23T21:05:53,789 INFO [main] org.apache.druid.query.lookup.LookupReferencesManager - LookupExtractorFactoryContainerProvider is stopping.
2019-12-23T21:05:53,789 INFO [LookupExtractorFactoryContainerProvider-MainThread] org.apache.druid.query.lookup.LookupReferencesManager - Lookup Management loop exited, Lookup notices are not handled anymore.
2019-12-23T21:05:53,789 INFO [main] org.apache.druid.query.lookup.LookupReferencesManager - LookupExtractorFactoryContainerProvider is stopped.
2019-12-23T21:05:53,789 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.discovery.DruidLeaderClient.stop()] on object[org.apache.druid.discovery.DruidLeaderClient@9263c54].
2019-12-23T21:05:53,789 INFO [main] org.apache.druid.discovery.DruidLeaderClient - Stopped.
2019-12-23T21:05:53,789 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.curator.discovery.ServerDiscoverySelector.stop() throws java.io.IOException] on object[org.apache.druid.curator.discovery.ServerDiscoverySelector@4d7cac24].
2019-12-23T21:05:53,789 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider.stop()] on object[org.apache.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider@5e2a6991].
2019-12-23T21:05:53,790 INFO [main] org.apache.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider - stopping
2019-12-23T21:05:53,790 INFO [main] org.apache.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider - stopped
2019-12-23T21:05:53,790 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.java.util.http.client.NettyHttpClient.stop()] on object[org.apache.druid.java.util.http.client.NettyHttpClient@20a3e10c].
2019-12-23T21:05:53,803 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.java.util.emitter.service.ServiceEmitter.close() throws java.io.IOException] on object[ServiceEmitter{serviceDimensions={service=middlemanager, host=192.168.51.36:8119, version=0.16.0-incubating-iap1}, emitter=org.apache.druid.java.util.emitter.core.NoopEmitter@53311681}].
2019-12-23T21:05:53,803 INFO [main] org.apache.druid.curator.CuratorModule - Stopping Curator
2019-12-23T21:05:53,808 INFO [Curator-Framework-0] org.apache.curator.framework.imps.CuratorFrameworkImpl - backgroundOperationsLoop exiting
2019-12-23T21:05:53,812 INFO [main] org.apache.zookeeper.ZooKeeper - Session: 0x6a000139f64e6615 closed
2019-12-23T21:05:53,812 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle [module] stage [INIT]
2019-12-23T21:05:53,812 INFO [main-EventThread] org.apache.zookeeper.ClientCnxn - EventThread shut down for session: 0x6a000139f64e6615
2019-12-23T21:05:53,812 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner.stop()] on object[org.apache.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner@2f04993d].
Finished peon task
```
here is the task definition:
```js
{
"type": "index_kafka",
"id": "index_kafka_apm-span-second_28bbb49e5a89ee5_encagppk",
"resource": {
"availabilityGroup": "index_kafka_apm-span-second_28bbb49e5a89ee5",
"requiredCapacity": 1
},
"dataSchema": {
"dataSource": "apm-span-second",
"parser": {
"type": "string",
"parseSpec": {
"format": "json",
"timestampSpec": {
"column": "timestamp",
"format": "auto"
},
"dimensionsSpec": {
"dimensions": []
}
}
},
"metricsSpec": [
{
"type": "count",
"name": "count"
},
{
"type": "longSum",
"name": "thp",
"fieldName": "thp",
"expression": null
},
{
"type": "longSum",
"name": "totalTime",
"fieldName": "totalTime",
"expression": null
},
{
"type": "longSum",
"name": "errs",
"fieldName": "errs",
"expression": null
}
],
"granularitySpec": {
"type": "uniform",
"segmentGranularity": "HOUR",
"queryGranularity": "SECOND",
"rollup": true,
"intervals": null
},
"transformSpec": {
"filter": null,
"transforms": []
}
},
"tuningConfig": {
"type": "KafkaTuningConfig",
"maxRowsInMemory": 1000000,
"maxBytesInMemory": 0,
"maxRowsPerSegment": 5000000,
"maxTotalRows": 20000000,
"intermediatePersistPeriod": "PT10M",
"basePersistDirectory": "/tmp/1575449145912-0",
"maxPendingPersists": 0,
"indexSpec": {
"bitmap": {
"type": "concise"
},
"dimensionCompression": "lz4",
"metricCompression": "lz4",
"longEncoding": "longs"
},
"indexSpecForIntermediatePersists": {
"bitmap": {
"type": "concise"
},
"dimensionCompression": "lz4",
"metricCompression": "lz4",
"longEncoding": "longs"
},
"buildV9Directly": true,
"reportParseExceptions": false,
"handoffConditionTimeout": 0,
"resetOffsetAutomatically": false,
"segmentWriteOutMediumFactory": null,
"intermediateHandoffPeriod": "P2147483647D",
"logParseExceptions": false,
"maxParseExceptions": 2147483647,
"maxSavedParseExceptions": 0,
"skipSequenceNumberAvailabilityCheck": false
},
"ioConfig": {
"type": "kafka",
"taskGroupId": 0,
"baseSequenceName": "index_kafka_apm-span-second_28bbb49e5a89ee5",
"startPartitions": {
"type": "end",
"stream": "apm-span-stats",
"topic": "apm-span-stats",
"partitionSequenceNumberMap": {
"0": 27344021
},
"partitionOffsetMap": {
"0": 27344021
}
},
"endPartitions": {
"type": "end",
"stream": "apm-span-stats",
"topic": "apm-span-stats",
"partitionSequenceNumberMap": {
"0": 9223372036854776000
},
"partitionOffsetMap": {
"0": 9223372036854776000
}
},
"startSequenceNumbers": {
"type": "start",
"stream": "apm-span-stats",
"topic": "apm-span-stats",
"partitionSequenceNumberMap": {
"0": 27344021
},
"partitionOffsetMap": {
"0": 27344021
},
"exclusivePartitions": []
},
"endSequenceNumbers": {
"type": "end",
"stream": "apm-span-stats",
"topic": "apm-span-stats",
"partitionSequenceNumberMap": {
"0": 9223372036854776000
},
"partitionOffsetMap": {
"0": 9223372036854776000
}
},
"consumerProperties": {
"bootstrap.servers": "192.168.53.248:9092,192.168.21.118:9092,192.168.91.80:9092"
},
"pollTimeout": 100,
"useTransaction": true,
"minimumMessageTime": null,
"maximumMessageTime": null
},
"context": {
"forceTimeChunkLock": true,
"checkpoints": "{\"0\":{\"0\":27344021}}",
"IS_INCREMENTAL_HANDOFF_SUPPORTED": true
},
"groupId": "index_kafka_apm-span-second",
"dataSource": "apm-span-second"
}
```
----------------------------------------------------------------
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.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org