io.druid.server.lookup.cache.LookupCoordinatorManager - Failed-Druid -0.10.1

TROUBLESHOOTING Google Groups
#1

Hi
When loading lookup cache value in druid - 0.10.1 version getting below error. Need help.

  1. curl -H “Content-Type: application/json” --data @lookup_script.json http://13.211.100.5:8081/druid/coordinator/v1/lookups/config

  2. **curl -X GET http://localhost:8082/druid/listen/v1/lookups **

{“current”:{},“toLoad”:{},“toDrop”:}

  1. curl -X GET http://localhost:8082/status

{“name”:“io.druid.server.lookup.namespace.NamespaceExtractionModule”,“artifact”:"druid-lookups-cached-global",“version”:“0.12.0”}],“memory”:{“maxMemory”:10737418240,“totalMemory”:10737418240,“freeMemory”:9315317144,“usedMemory”:1422101096}

Added “druid-lookups-cached-global” in load list and restarted all the services.

In coordinator log:

2019-06-04T10:01:32,626 INFO [DatabaseSegmentManager-Exec–0] io.druid.metadata.SQLMetadataSegmentManager - Polled and found 14,405 segments in the database

2019-06-04T10:01:48,329 INFO [GraphiteEmitter-0] io.druid.emitter.graphite.GraphiteEmitter - trying to connect to graphite server

2019-06-04T10:01:48,804 INFO [DatabaseRuleManager-Exec–0] io.druid.metadata.SQLMetadataRuleManager - Polled and found rules for 8 datasource(s)

2019-06-04T10:02:18,582 ERROR [LookupCoordinatorManager–4] io.druid.server.lookup.cache.LookupCoordinatorManager - Failed to finish lookup management loop.: {class=io.druid.server.lookup.cache.LookupCoordinatorManager, exceptionType=class java.lang.IllegalStateException, exceptionMessage=null}

java.lang.IllegalStateException

at com.google.common.base.Preconditions.checkState(Preconditions.java:161) ~[guava-16.0.1.jar:?]

at com.google.common.net.HostAndPort.getPort(HostAndPort.java:110) ~[guava-16.0.1.jar:?]

at io.druid.server.lookup.cache.LookupCoordinatorManager.lookupManagementLoop(LookupCoordinatorManager.java:517) ~[druid-server-0.10.1.jar:0.10.1]

at com.google.common.util.concurrent.MoreExecutors$ScheduledListeningDecorator$NeverSuccessfulListenableFutureTask.run(MoreExecutors.java:582) [guava-16.0.1.jar:?]

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_171]

at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_171]

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_171]

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_171]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_171]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_171]

at java.lang.Thread.run(Thread.java:748) [?:1.8.0_171]

2019-06-04T10:02:18,583 ERROR [LookupCoordinatorManager–4] io.druid.emitter.graphite.GraphiteEmitter - The following alert is dropped, description is [Failed to finish lookup management loop.], severity is [component-failure]

2019-06-04T10:02:20,613 INFO [Coordinator-Exec–0] io.druid.server.coordinator.helper.DruidCoordinatorSegmentInfoLoader - Starting coordination. Getting available segments.

2019-06-04T10:02:20,621 INFO [Coordinator-Exec–0] io.druid.server.coordinator.helper.DruidCoordinatorSegmentInfoLoader - Found [14,405] available segments.

2019-06-04T10:02:20,654 INFO [Coordinator-Exec–0] io.druid.server.coordinator.ReplicationThrottler - [_default_tier]: Replicant create queue is empty.

2019-06-04T10:02:20,663 INFO [Coordinator-Exec–0] io.druid.server.coordinator.LoadQueuePeon - Asking server peon[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] to drop segment[links_v1.0_2019-04-24T03:00:00.000Z_2019-04-24T04:00:00.000Z_2019-04-27T17:55:42.372Z]

2019-06-04T10:02:20,670 INFO [Coordinator-Exec–0] io.druid.server.coordinator.LoadQueuePeon - Asking server peon[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] to drop segment[staypoint_v1.0_2018-10-23T11:00:00.000Z_2018-10-23T12:00:00.000Z_2019-05-08T17:21:16.449Z_2]

2019-06-04T10:02:20,674 INFO [Master-PeonExec–0] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] dropping [links_v1.0_2019-04-24T03:00:00.000Z_2019-04-24T04:00:00.000Z_2019-04-27T17:55:42.372Z]

2019-06-04T10:02:20,674 INFO [Master-PeonExec–0] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] processing segment[links_v1.0_2019-04-24T03:00:00.000Z_2019-04-24T04:00:00.000Z_2019-04-27T17:55:42.372Z]

2019-06-04T10:02:20,680 INFO [Coordinator-Exec–0] io.druid.server.coordinator.LoadQueuePeon - Asking server peon[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] to drop segment[staypoint_v1.0_2018-09-08T01:00:00.000Z_2018-09-08T02:00:00.000Z_2019-05-08T23:32:52.113Z]

2019-06-04T10:02:20,684 INFO [main-EventThread] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] done processing [/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083/links_v1.0_2019-04-24T03:00:00.000Z_2019-04-24T04:00:00.000Z_2019-04-27T17:55:42.372Z]

2019-06-04T10:02:20,724 INFO [Master-PeonExec–0] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] dropping [staypoint_v1.0_2018-10-23T11:00:00.000Z_2018-10-23T12:00:00.000Z_2019-05-08T17:21:16.449Z_2]

2019-06-04T10:02:20,724 INFO [Master-PeonExec–0] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] processing segment[staypoint_v1.0_2018-10-23T11:00:00.000Z_2018-10-23T12:00:00.000Z_2019-05-08T17:21:16.449Z_2]

2019-06-04T10:02:20,732 INFO [main-EventThread] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] done processing [/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083/staypoint_v1.0_2018-10-23T11:00:00.000Z_2018-10-23T12:00:00.000Z_2019-05-08T17:21:16.449Z_2]

2019-06-04T10:02:20,749 INFO [Coordinator-Exec–0] io.druid.server.coordinator.helper.DruidCoordinatorBalancer - Moving [staypoint_v1.0_2019-04-23T04:00:00.000Z_2019-04-23T05:00:00.000Z_2019-04-27T17:00:21.955Z] from [ip-10-0-1-68.ap-southeast-2.compute.internal:8083] to [ip-10-0-1-46.ap-southeast-2.compute.internal:8083]

2019-06-04T10:02:20,749 INFO [Coordinator-Exec–0] io.druid.server.coordinator.LoadQueuePeon - Asking server peon[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] to load segment[staypoint_v1.0_2019-04-23T04:00:00.000Z_2019-04-23T05:00:00.000Z_2019-04-27T17:00:21.955Z]

2019-06-04T10:02:20,749 INFO [Coordinator-Exec–0] io.druid.server.coordinator.helper.DruidCoordinatorBalancer - [_default_tier]: Segments Moved: [1] Segments Let Alone: [0]

2019-06-04T10:02:20,749 INFO [Coordinator-Exec–0] io.druid.server.coordinator.helper.DruidCoordinatorLogger - [_default_tier] : Assigned 0 segments among 2 servers

2019-06-04T10:02:20,749 INFO [Coordinator-Exec–0] io.druid.server.coordinator.helper.DruidCoordinatorLogger - [_default_tier] : Dropped 3 segments among 2 servers

2019-06-04T10:02:20,749 INFO [Coordinator-Exec–0] io.druid.server.coordinator.helper.DruidCoordinatorLogger - [_default_tier] : Moved 1 segment(s)

2019-06-04T10:02:20,749 INFO [Coordinator-Exec–0] io.druid.server.coordinator.helper.DruidCoordinatorLogger - [_default_tier] : Let alone 0 segment(s)

2019-06-04T10:02:20,749 INFO [Coordinator-Exec–0] io.druid.server.coordinator.helper.DruidCoordinatorLogger - Load Queues:

2019-06-04T10:02:20,749 INFO [Coordinator-Exec–0] io.druid.server.coordinator.helper.DruidCoordinatorLogger - Server[ip-10-0-1-68.ap-southeast-2.compute.internal:8083, historical, _default_tier] has 0 left to load, 0 left to drop, 0 bytes queued, 1,906,756,735,823 bytes served.

2019-06-04T10:02:20,749 INFO [Coordinator-Exec–0] io.druid.server.coordinator.helper.DruidCoordinatorLogger - Server[ip-10-0-1-46.ap-southeast-2.compute.internal:8083, historical, _default_tier] has 1 left to load, 1 left to drop, 103,304,272 bytes queued, 1,913,045,704,229 bytes served.

2019-06-04T10:02:20,774 INFO [Master-PeonExec–0] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] dropping [staypoint_v1.0_2018-09-08T01:00:00.000Z_2018-09-08T02:00:00.000Z_2019-05-08T23:32:52.113Z]

2019-06-04T10:02:20,774 INFO [Master-PeonExec–0] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] processing segment[staypoint_v1.0_2018-09-08T01:00:00.000Z_2018-09-08T02:00:00.000Z_2019-05-08T23:32:52.113Z]

2019-06-04T10:02:20,781 INFO [main-EventThread] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] done processing [/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083/staypoint_v1.0_2018-09-08T01:00:00.000Z_2018-09-08T02:00:00.000Z_2019-05-08T23:32:52.113Z]

2019-06-04T10:02:20,824 INFO [Master-PeonExec–0] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] loading [staypoint_v1.0_2019-04-23T04:00:00.000Z_2019-04-23T05:00:00.000Z_2019-04-27T17:00:21.955Z]

2019-06-04T10:02:20,825 INFO [Master-PeonExec–0] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] processing segment[staypoint_v1.0_2019-04-23T04:00:00.000Z_2019-04-23T05:00:00.000Z_2019-04-27T17:00:21.955Z]

2019-06-04T10:02:20,875 INFO [Master-PeonExec–0] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] skipping doNext() because something is currently loading[staypoint_v1.0_2019-04-23T04:00:00.000Z_2019-04-23T05:00:00.000Z_2019-04-27T17:00:21.955Z].

2019-06-04T10:02:20,925 INFO [Master-PeonExec–0] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] skipping doNext() because something is currently loading[staypoint_v1.0_2019-04-23T04:00:00.000Z_2019-04-23T05:00:00.000Z_2019-04-27T17:00:21.955Z].

2019-06-04T10:02:20,930 INFO [main-EventThread] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083] done processing [/druid/loadQueue/ip-10-0-1-46.ap-southeast-2.compute.internal:8083/staypoint_v1.0_2019-04-23T04:00:00.000Z_2019-04-23T05:00:00.000Z_2019-04-27T17:00:21.955Z]

2019-06-04T10:02:33,359 INFO [DatabaseSegmentManager-Exec–0] io.druid.metadata.SQLMetadataSegmentManager - Polled and found 14,405 segments in the database

2019-06-04T10:02:48,329 INFO [GraphiteEmitter-0] io.druid.emitter.graphite.GraphiteEmitter - trying to connect to graphite server

2019-06-04T10:02:48,806 INFO [DatabaseRuleManager-Exec–0] io.druid.metadata.SQLMetadataRuleManager - Polled and found rules for 8 datasource(s)

2019-06-04T10:03:33,860 INFO [DatabaseSegmentManager-Exec–0] io.druid.metadata.SQLMetadataSegmentManager - Polled and found 14,405 segments in the database

2019-06-04T10:03:48,329 INFO [GraphiteEmitter-0] io.druid.emitter.graphite.GraphiteEmitter - trying to connect to graphite server

2019-06-04T10:03:48,807 INFO [DatabaseRuleManager-Exec–0] io.druid.metadata.SQLMetadataRuleManager - Polled and found rules for 8 datasource(s)

2019-06-04T10:04:18,585 ERROR [LookupCoordinatorManager–4] io.druid.server.lookup.cache.LookupCoordinatorManager - Failed to finish lookup management loop.: {class=io.druid.server.lookup.cache.LookupCoordinatorManager, exceptionType=class java.lang.IllegalStateException, exceptionMessage=null}

java.lang.IllegalStateException

at com.google.common.base.Preconditions.checkState(Preconditions.java:161) ~[guava-16.0.1.jar:?]

at com.google.common.net.HostAndPort.getPort(HostAndPort.java:110) ~[guava-16.0.1.jar:?]

at io.druid.server.lookup.cache.LookupCoordinatorManager.lookupManagementLoop(LookupCoordinatorManager.java:517) ~[druid-server-0.10.1.jar:0.10.1]

at com.google.common.util.concurrent.MoreExecutors$ScheduledListeningDecorator$NeverSuccessfulListenableFutureTask.run(MoreExecutors.java:582) [guava-16.0.1.jar:?]

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_171]

at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_171]

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_171]

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_171]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_171]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_171]

at java.lang.Thread.run(Thread.java:748) [?:1.8.0_171]

2019-06-04T10:04:18,585 ERROR [LookupCoordinatorManager–4] io.druid.emitter.graphite.GraphiteEmitter - The following alert is dropped, description is [Failed to finish lookup management loop.], severity is [component-failure]

2019-06-04T10:04:34,366 INFO [DatabaseSegmentManager-Exec–0] io.druid.metadata.SQLMetadataSegmentManager - Polled and found 14,405 segments in the database

2019-06-04T10:04:48,329 INFO [GraphiteEmitter-0] io.druid.emitter.graphite.GraphiteEmitter - trying to connect to graphite server

2019-06-04T10:04:48,809 INFO [DatabaseRuleManager-Exec–0] io.druid.metadata.SQLMetadataRuleManager - Polled and found rules for 8 datasource(s)

#2

Hi

In coordinator if i look for lookups it is giving ["__default"]

curl -X GET http://localhost:8081/druid/coordinator/v1/lookups

["__default"]

#3

This (__default) is the default tier for lookups. If you want to configure a different tier name you can change the druid.lookup.lookupTier property in the Historical, Broker and Middle Manager runtime.properties.

What is the tier name you used for POSTing (loading) lookups to Druid ?

Thanks,

Sashi

#4

Hi
curl -H “Content-Type: application/json” --data @custom-json-lookup.json http://localhost:8081/druid/coordinator/v1/lookups/config

curl -X GET http://localhost:8081/druid/coordinator/v1/lookups/status/__default

{“pointlookup”:{“loaded”:false},“point_v1.0”:{“loaded”:false}}

But custom-json-lookup is not loaded in cache. In coordinator log I am able to see the below error:

ERROR [LookupCoordinatorManager–2] io.druid.server.lookup.cache.LookupCoordinatorManager - Failed to finish lookup management loop.: {class=io.druid.server.lookup.cache.LookupCoordinatorManager, exceptionType=class java.lang.IllegalStateException, exceptionMessage=null}

java.lang.IllegalStateException

#5

Hi,

I’m not sure that could be the cause of your issue but I see your are running Druid 0.10.1 and the extension is 0.12

Are you sure that both are compatibles ?

#6

The load status of the lookups is false. There could be several reasons for this - incorrect metadata store connection details, mismatch of column names etc.

  1. Can you share the contents of custom-json-lookup.json ?
  2. Did you check the historical and broker logs for errors ?
#7

Hi
We have broker in 0.12 version and other services in 0.10 version.

I restarted all the services and watched the log.

In coordinator log, below is the messagetill today and still running :

2019-06-09T02:59:16,435 INFO [main-EventThread] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-68.ap-southeast-2.compute.internal:8083] done processing [/druid/loadQueue/ip-xx.xx.xx.xx.compute.internal:8083/point_v12018-09-11T23:00:00.000Z_2018-09-12T00:00:00.000Z_2019-05-09T01:15:24.314Z_2]

#8

Hi
We have broker in 0.12 version and other services in 0.10 version.

I restarted all the services and watched the log.

In coordinator log, below is the messagetill today and still running :

2019-06-09T02:59:16,435 INFO [main-EventThread] io.druid.server.coordinator.LoadQueuePeon - Server[/druid/loadQueue/ip-10-0-1-68.ap-southeast-2.compute.internal:8083] done processing [/druid/loadQueue/ip-xx.xx.xx.xx.compute.internal:8083/point_v12018-09-11T23:00:00.000Z_2018-09-12T00:00:00.000Z_2019-05-09T01:15:24.314Z_2]

and

my custom-json-lookup.json is

{

“__default”: {

 "country": {

   "version": "v1",

   "lookupExtractorFactory": {

     "type": "cachedNamespace",

     "extractionNamespace": {

       "type": "uri",

       "uri": "file:/Users/pk/lookuplocal/country.json",

       "namespaceParseSpec": {

         "format": "customJson",

         "keyFieldName": "code",

         "valueFieldName": "name"

       },

       "pollPeriod": "PT30S"

     },

     "firstCacheTimeout": 0

   }

 }

}

}

#9

Is the file URI scheme you provided correct ? It should look like file:///Users/pk/lookuplocal/country.json or file://localhost/Users/pk/lookuplocal/country.json. Also make sure the json input is in proper format as mentioned in the docs.