MiddleManager not spawning peons for kafka indexing task

[Ben Vogan]

Hi all,

My Druid cluster got itself into a bad state last weekend and I have been unable to get it working.  My peons started getting OOM errors and eventually seemed to get stuck as zombie processes.  I restarted the whole cluster but the processes didn't go away so I killed them manually.  Now no indexing tasks will run.  I get one that transfers into a running state but never gets a peon process and I get one that sits pending forever.

In the overlord log I see that it is trying to start a task:

2016-07-20T16:41:07,232 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.RemoteTaskRunner - Coordinator asking Worker[druid-data001.internal.shopkick.com:8091] to add task[index_kafka_business_events_test_d6c6c7d01c7c8a6_mmihlojc]

2016-07-20T16:41:07,309 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.RemoteTaskRunner - Task index_kafka_business_events_test_d6c6c7d01c7c8a6_mmihlojc switched from pending to running (on [druid-data001.internal.shopkick.com:8091])

2016-07-20T16:41:07,311 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_business_events_test_d6c6c7d01c7c8a6_mmihlojc] status changed to [RUNNING].

In the coordinator web console I see that task as running, but there is no log file and there is no process started on druid-data001 for it.

In the middle manager log I see:

2016-07-20T16:41:07,314 ERROR [TaskMonitorCache-0] org.apache.curator.framework.recipes.cache.PathChildrenCache -

com.fasterxml.jackson.databind.JsonMappingException: Could not resolve type id 'index_kafka' into a subtype of [simple type, class io.druid.indexing.common.task.Task]

 at [Source: [B@5035ce8a; line: 1, column: 2]

        at com.fasterxml.jackson.databind.JsonMappingException.from(JsonMappingException.java:148) ~[jackson-databind-2.4.6.jar:2.4.6]

        at com.fasterxml.jackson.databind.DeserializationContext.unknownTypeException(DeserializationContext.java:862) ~[jackson-databind-2.4.6.jar:2.4.6]

        at com.fasterxml.jackson.databind.jsontype.impl.TypeDeserializerBase._findDeserializer(TypeDeserializerBase.java:167) ~[jackson-databind-2.4.6.jar:2.4.6]

        at com.fasterxml.jackson.databind.jsontype.impl.AsPropertyTypeDeserializer._deserializeTypedForId(AsPropertyTypeDeserializer.java:99) ~[jackson-databind-2.4.6.jar:2.4.6]

        at com.fasterxml.jackson.databind.jsontype.impl.AsPropertyTypeDeserializer.deserializeTypedFromObject(AsPropertyTypeDeserializer.java:84) ~[jackson-databind-2.4.6.jar:2.4.6]

        at com.fasterxml.jackson.databind.deser.AbstractDeserializer.deserializeWithType(AbstractDeserializer.java:132) ~[jackson-databind-2.4.6.jar:2.4.6]

        at com.fasterxml.jackson.databind.deser.impl.TypeWrappedDeserializer.deserialize(TypeWrappedDeserializer.java:41) ~[jackson-databind-2.4.6.jar:2.4.6]

        at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:3066) ~[jackson-databind-2.4.6.jar:2.4.6]

        at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2230) ~[jackson-databind-2.4.6.jar:2.4.6]

        at io.druid.indexing.worker.WorkerTaskMonitor$1.childEvent(WorkerTaskMonitor.java:121) ~[druid-indexing-service-0.9.1-SNAPSHOT.jar:0.9.1-SNAPSHOT]

        at org.apache.curator.framework.recipes.cache.PathChildrenCache$5.apply(PathChildrenCache.java:518) [curator-recipes-2.9.1.jar:?]

        at org.apache.curator.framework.recipes.cache.PathChildrenCache$5.apply(PathChildrenCache.java:512) [curator-recipes-2.9.1.jar:?]

        at org.apache.curator.framework.listen.ListenerContainer$1.run(ListenerContainer.java:92) [curator-framework-2.9.1.jar:?]

        at com.google.common.util.concurrent.MoreExecutors$SameThreadExecutorService.execute(MoreExecutors.java:297) [guava-16.0.1.jar:?]

        at org.apache.curator.framework.listen.ListenerContainer.forEach(ListenerContainer.java:83) [curator-framework-2.9.1.jar:?]

        at org.apache.curator.framework.recipes.cache.PathChildrenCache.callListeners(PathChildrenCache.java:509) [curator-recipes-2.9.1.jar:?]

        at org.apache.curator.framework.recipes.cache.EventOperation.invoke(EventOperation.java:35) [curator-recipes-2.9.1.jar:?]

        at org.apache.curator.framework.recipes.cache.PathChildrenCache$9.run(PathChildrenCache.java:766) [curator-recipes-2.9.1.jar:?]

        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [?:1.7.0_101]

        at java.util.concurrent.FutureTask.run(FutureTask.java:262) [?:1.7.0_101]

        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [?:1.7.0_101]

        at java.util.concurrent.FutureTask.run(FutureTask.java:262) [?:1.7.0_101]

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [?:1.7.0_101]

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [?:1.7.0_101]

        at java.lang.Thread.run(Thread.java:745) [?:1.7.0_101]

Any help?

--Ben

[Gian Merlino]

Hey Ben,

This looks like an error that would happen if the middleManager didn't load the druid-kafka-indexing-service extension. Could you double-check that it's configured to load the extension (druid.extensions.loadList in common.runtime.properties) and that it logs a message on startup saying that it's loading the extension?

Gian

--
You received this message because you are subscribed to the Google Groups "Druid User" group.
To unsubscribe from this group and stop receiving emails from it, send an email to druid-user+...@googlegroups.com.
To post to this group, send email to druid...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/druid-user/afcfc544-516c-43ac-9f8f-8683ca252797%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Ben Vogan]

Thanks Gian.  I'm not entirely sure what is wrong because I have the extension listed in my _common/common.runtime.properties file, but in the log on druid-data001 I don't see the extension being loaded.  I added the druid-kafka-indexing-service extension to the middle manager config file directly and now I've gotten past that error.  I'm sure I've just screwed something up moving files around.

However, now my tasks are stuck waiting on locks.  How do I free up a stuck lock?

Thanks for your help.

--Ben

[Gian Merlino]

Locks correspond to currently-running tasks, and should free up when the task exits or is killed. If you want to "help" it along you can kill the task manually (see shutdown api at: http://druid.io/docs/latest/design/indexing-service.html).

Gian

--

You received this message because you are subscribed to the Google Groups "Druid User" group.
To unsubscribe from this group and stop receiving emails from it, send an email to druid-user+...@googlegroups.com.
To post to this group, send email to druid...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/druid-user/d49335d9-93b7-4116-ac98-486d89c6af69%40googlegroups.com.

[Ben Vogan]

The locks timed out eventually, but the tasks still do not run.  One appears to be in a running state but no peon process is launched and the other sits pending.  Clicking on the log links gives an error that the log file doesn't exist.  See the attached images from the console:

[Gian Merlino]

Hmm, the system might have got into a funny state due to the extension loading problems on the middleManager. Perhaps try shutting down the middleManager, killing/waiting for all the tasks on the overlord such that there's nothing left running, and then starting the middleManager up again.

Gian

To view this discussion on the web visit https://groups.google.com/d/msgid/druid-user/8ea910c8-34b0-44da-8a58-2c3213acf25f%40googlegroups.com.

[Ben Vogan]

I tried to shutdown the tasks like so:

curl -X 'POST' http://druid-master001:8090/druid/indexer/v1/task/index_kafka_sor_business_event_success_v1_02e5539d885b011_nabicilj/shutdown

But I see:

2016-07-20T19:08:45,315 INFO [TaskQueue-Manager] io.druid.indexing.overlord.TaskQueue - Asking taskRunner to clean up 1 tasks.

2016-07-20T19:08:45,315 INFO [TaskQueue-Manager] io.druid.indexing.overlord.RemoteTaskRunner - Can't shutdown! No worker running task index_kafka_business_events_test_d6c6c7d01c7c8a6_bfcgmfal

In the logs.

On Wednesday, July 20, 2016 at 11:31:49 AM UTC-6, Gian Merlino wrote:

[Gian Merlino]

Does restarting the overlord help?

Gian

To view this discussion on the web visit https://groups.google.com/d/msgid/druid-user/b9bd96ec-49c0-45e2-a819-0e1c3ff512c8%40googlegroups.com.

[Ben Vogan]

No.  I have restarted everything except my brokers and it hasn't made any difference.  After a restart I end up with 2 tasks in the wait state and they eventually transition into the same state as before (one supposedly running but not, and the other pending).

[Gian Merlino]

Hmm, a wild guess: are those two tasks meant to be replicas of each other (do you have "replicas" > 1)? If so, do you have more than one middleManager running? Replicas can't run on the same middleManager, so one would stay pending until you started another middleManager.

Gian

To view this discussion on the web visit https://groups.google.com/d/msgid/druid-user/600da43b-453f-4580-b24c-e2f682ba83db%40googlegroups.com.

[Ben Vogan]

They are not replicas of each other.  There are 2 separate ingestion specs with replicas=1.  I also have 2 middle manager instances running.

[Gian Merlino]

Hmm, that's strange. Are there any exceptions on the middleManagers or overlords after you brought them down and then brought them back up? Does it help if you take them all (overlord/MM) down for longer than your zookeeper session timeout (default 30sec) and then bring them back up? Do things work if you try the same supervisor specs on a fresh install?

Those questions above are geared towards figuring out if what's wrong is some confused state in ZK, potentially fallout from the PathChildrenCache error that started all this (taking everything down for longer than the timeout should help with that) or if something else is going on.

Gian

To view this discussion on the web visit https://groups.google.com/d/msgid/druid-user/df307b81-f82b-44cf-b355-bcd4ea739548%40googlegroups.com.

[Ben Vogan]

I took them down for a few minutes and brought them back up and there was no change.  I do not have systems handy for a second installation at the moment.  Will changing the HDFS path, Zookeeper path, local data path for the MM, and MySQL database in config be enough to look like a fresh install?  Is there anything else I would have to change?

[Gian Merlino]

I think that should be enough, yeah.

Gian

To view this discussion on the web visit https://groups.google.com/d/msgid/druid-user/720c081e-d459-4058-b52b-3269ceb6476c%40googlegroups.com.

[Ben Vogan]

It does not work.  Which is exceedingly odd since it worked on Friday.  Here is the payload of the currently stuck task.  For brevity I pared down the number of dimensions.  One thing I notice is that I had put "useEarliestOffset" : true in the ioConfig but do not see it in the payload.

{

   "task":"index_kafka_business_events_test_a5e0e81bf9ebd4b_dagjpakj",

   "payload":{

      "id":"index_kafka_business_events_test_a5e0e81bf9ebd4b_dagjpakj",

      "resource":{

         "availabilityGroup":"index_kafka_business_events_test_a5e0e81bf9ebd4b",

         "requiredCapacity":1

      },

      "dataSchema":{

         "dataSource":"business_events_test",

         "parser":{

            "type":"avro_stream",

            "avroBytesDecoder":{

               "type":"schema_repo",

               "subjectAndIdConverter":{

                  "type":"avro_1124",

                  "topic":"raw_shopkick_pylons_weblog_avro_v2"

               },

               "schemaRepository":{

                  "type":"avro_1124_rest_client",

                  "url":"http://data-catalog001:8081"

               }

            },

            "parseSpec":{

               "format":"timeAndDims",

               "timestampSpec":{

                  "column":"event_time",

                  "format":"auto"

               },

               "dimensionsSpec":{

                  "dimensions":[

                     "session_type",

                     "event_type",

                     "event_subtype",

                     "event_status",

                     "event_status_subcode",

                     "event_category_type",

                     "event_city",

                     "event_region",

                     "event_country",

                     "event_dma",

                     "user_country",

                     "client_app_version",

                     "client_ip_address",

                     "app_id",

                     "product_id",

                     "user_id",

                     "location_id",

                     "device_id",

                     "session_start_time",

                     "client_event_time",

                     "client_request_time",

                     "server_request_time",

                     "user_registration_time"

                  ],

                  "spatialDimensions":[

                     {

                        "dimName":"event_coordinates",

                        "dims":[

                           "event_latitude",

                           "event_longitude"

                        ]

                     },

                     {

                        "dimName":"location_coordinates",

                        "dims":[

                           "location_latitude",

                           "location_longitude"

                        ]

                     }

                  ]

               }

            }

         },

         "metricsSpec":[

            {

               "type":"count",

               "name":"count"

            },

            {

               "type":"longSum",

               "name":"transaction_kicks",

               "fieldName":"transaction_kicks"

            },

            {

               "type":"longSum",

               "name":"transaction_cost",

               "fieldName":"transaction_cost"

            },

            {

               "type":"longSum",

               "name":"transaction_revenue",

               "fieldName":"transaction_revenue"

            },

            {

               "type":"hyperUnique",

               "name":"users",

               "fieldName":"user_id"

            },

            {

               "type":"hyperUnique",

               "name":"user_devices",

               "fieldName":"user_device_id"

            },

            {

               "type":"hyperUnique",

               "name":"locations",

               "fieldName":"location_id"

            }

         ],

         "granularitySpec":{

            "type":"uniform",

            "segmentGranularity":"HOUR",

            "queryGranularity":{

               "type":"duration",

               "duration":60000,

               "origin":"1970-01-01T00:00:00.000Z"

            },

            "intervals":null

         }

      },

      "tuningConfig":{

         "type":"kafka",

         "maxRowsInMemory":75000,

         "maxRowsPerSegment":5000000,

         "intermediatePersistPeriod":"PT10M",

         "basePersistDirectory":"/services/druid/data/tmp/1469048827697-0",

         "maxPendingPersists":0,

         "indexSpec":{

            "bitmap":{

               "type":"concise"

            },

            "dimensionCompression":null,

            "metricCompression":null

         },

         "buildV9Directly":false,

         "reportParseExceptions":false,

         "handoffConditionTimeout":0

      },

      "ioConfig":{

         "type":"kafka",

         "baseSequenceName":"index_kafka_business_events_test_a5e0e81bf9ebd4b",

         "startPartitions":{

            "topic":"raw_shopkick_pylons_weblog_avro_v1",

            "partitionOffsetMap":{

               "0":2705052,

               "1":2661700,

               "2":2628560,

               "3":2773322,

               "4":2676076,

               "5":2753075,

               "6":2692404,

               "7":2675881

            }

         },

         "endPartitions":{

            "topic":"raw_shopkick_pylons_weblog_avro_v1",

            "partitionOffsetMap":{

               "0":9223372036854775807,

               "1":9223372036854775807,

               "2":9223372036854775807,

               "3":9223372036854775807,

               "4":9223372036854775807,

               "5":9223372036854775807,

               "6":9223372036854775807,

               "7":9223372036854775807

            }

         },

         "consumerProperties":{

            "max.poll.records":"75000",

            "bootstrap.servers":"kafka001:9092,kafka002:9092,kafka003:9092"

         },

         "useTransaction":true,

         "pauseAfterRead":false,

         "minimumMessageTime":null

      },

      "context":{

      },

      "groupId":"index_kafka_business_events_test",

      "dataSource":"business_events_test"

[Ben Vogan]

My apologies.  I had missed changing the zookeeper base path on the overlord node so it wasn't finding the middle manager nodes.  Fixed that and now both tasks are indexing.

I would still like to know what happened to the other environment.  I'm basically still in evaluation/test mode so this isn't production data yet.  However if this had been production data I would need a good way of recovering from this scenario without having to essentially wipe all druid data and start over.