SegmentInsertAction fails with "Segments not covered by locks for task"

[Wayne Adams]

Hi, all:

  [This is on a build of 0.6.75, running in remote mode with 2 middle managers].

  Can someone explain what this means?  I have the simplest index job imaginable -- 3 json records spaced at 5 seconds apart, to demonstrate a simple index job, and I can't get it to work.  I'm assuming it must have something to do with my unique combination of timestamps, index granularity, rollup granularity, and intervals, but it's nothing obvious to me.  Here's my data:

{"timestamp":1397248006000, "label":"A", "event_count":1, "events":1}
{"timestamp":1397248011000, "label":"A", "event_count":1, "events":5}
{"timestamp":1397248016000, "label":"A", "event_count":1, "events":2}

I'm trying to do a simple rollup demonstration.  My task config file:

{
  "type" : "index",
  "id" : "smallCountExample_14apr2014_09",
  "dataSource" : "smallCountExample",
  "granularitySpec" : {
    "type" : "uniform",
    "gran" : "DAY",
    "intervals" : [ "2014-04-11/2014-04-12" ]
  },
  "aggregators" : [
    { "type" : "count", "name" : "row_count" },
    { "type" : "longSum", "name" : "event_count", "fieldName" : "event_count" },
    { "type" : "longSum", "name" : "events", "fieldName": "events" }
  ],
  "indexGranularity" : "minute",
  "firehose" : {
    "type" : "local",
    "baseDir" : "/usr/local/share/druid/data",
    "filter" : "smallSample.json",
    "parser" : {
      "timestampSpec" : {
        "column" : "timestamp",
        "format" : "millis"
      },
      "data" : {
        "format" : "json",
        "dimensions" : [ "label" ]
      }
    }
  }
}

The segment build succeeds (including persist to deep store), but then I get an exception:

2014-04-14 20:15:09,368 INFO  io.druid.indexing.overlord.HeapMemoryTaskStorage [qtp214056660-27]: Inserting task smallCountExample_14apr2014_10 with status: TaskStatus{id=smallCountExample_14apr2014_10, status=RUNNING, duration=-1}
2014-04-14 20:15:09,370 INFO  io.druid.indexing.common.actions.LocalTaskActionClient [TaskQueue-Manager]: Performing action for task[smallCountExample_14apr2014_10]: LockTryAcquireAction{interval=2014-04-11T00:00:00.000Z/2014-04-12T00:00:00.000Z}
2014-04-14 20:15:09,371 INFO  io.druid.indexing.overlord.TaskLockbox [TaskQueue-Manager]: Created new TaskLockPosse: TaskLockPosse{taskLock=TaskLock{groupId=smallCountExample_14apr2014_10, dataSource=smallCountExample, interval=2014-04-11T00:00:00.000Z/2014-04-12T00:00:00.000Z, version=2014-04-14T20:15:09.370Z}, taskIds=[]}
2014-04-14 20:15:09,371 INFO  io.druid.indexing.overlord.TaskLockbox [TaskQueue-Manager]: Added task[smallCountExample_14apr2014_10] to TaskLock[smallCountExample_14apr2014_10]
2014-04-14 20:15:09,371 INFO  io.druid.indexing.overlord.TaskQueue [TaskQueue-Manager]: Asking taskRunner to run: smallCountExample_14apr2014_10
2014-04-14 20:15:09,371 INFO  io.druid.indexing.overlord.RemoteTaskRunner [TaskQueue-Manager]: Added pending task smallCountExample_14apr2014_10
2014-04-14 20:15:09,373 INFO  io.druid.indexing.overlord.RemoteTaskRunner [pool-10-thread-1]: Coordinator asking Worker[localhost:8079] to add task[smallCountExample_14apr2014_10]
2014-04-14 20:15:09,426 INFO  io.druid.indexing.overlord.RemoteTaskRunner [pool-10-thread-1]: Task smallCountExample_14apr2014_10 switched from pending to running (on [localhost:8079])
2014-04-14 20:15:09,541 INFO  io.druid.indexing.overlord.RemoteTaskRunner [PathChildrenCache-0]: Worker[localhost:8079] wrote RUNNING status for task: smallCountExample_14apr2014_10
2014-04-14 20:15:12,223 INFO  io.druid.indexing.common.actions.LocalTaskActionClient [qtp214056660-22]: Performing action for task[smallCountExample_14apr2014_10]: LockTryAcquireAction{interval=2014-04-11T00:00:00.000Z/2014-04-12T00:00:00.000Z}
2014-04-14 20:15:12,225 INFO  io.druid.indexing.overlord.TaskLockbox [qtp214056660-22]: Task[smallCountExample_14apr2014_10] already present in TaskLock[smallCountExample_14apr2014_10]
2014-04-14 20:15:12,246 INFO  io.druid.indexing.common.actions.LocalTaskActionClient [qtp214056660-23]: Performing action for task[smallCountExample_14apr2014_10]: LockListAction{}
2014-04-14 20:15:12,420 INFO  io.druid.indexing.common.actions.LocalTaskActionClient [qtp214056660-24]: Performing action for task[smallCountExample_14apr2014_10]: SegmentInsertAction{segments=[DataSegment{size=974, shardSpec=NoneShardSpec, metrics=[row_count, event_count, events], dimensions=[label], version='2014-04-14T20:15:09.370Z', loadSpec={type=local, path=/druid/persist/smallcountexample/2014-04-11T00:00:00.000Z_2014-04-12T00:00:00.000Z/2014-04-14T20:15:09.370Z/0/index.zip}, interval=2014-04-11T00:00:00.000Z/2014-04-12T00:00:00.000Z, dataSource='smallcountexample', binaryVersion='9'}]}
2014-04-14 20:15:12,423 WARN  org.eclipse.jetty.servlet.ServletHandler [qtp214056660-24]: /druid/indexer/v1/action
com.metamx.common.ISE: Segments not covered by locks for task: smallCountExample_14apr2014_10
        at io.druid.indexing.common.actions.TaskActionToolbox.verifyTaskLocksAndSinglePartitionSettitude(TaskActionToolbox.java:95)
        at io.druid.indexing.common.actions.SegmentInsertAction.perform(SegmentInsertAction.java:82)
        at io.druid.indexing.common.actions.SegmentInsertAction.perform(SegmentInsertAction.java:34)
        at io.druid.indexing.common.actions.LocalTaskActionClient.submit(LocalTaskActionClient.java:64)
        at io.druid.indexing.overlord.http.OverlordResource$3.apply(OverlordResource.java:235)
        at io.druid.indexing.overlord.http.OverlordResource$3.apply(OverlordResource.java:224)
        at io.druid.indexing.overlord.http.OverlordResource.asLeaderWith(OverlordResource.java:457)
        at io.druid.indexing.overlord.http.OverlordResource.doAction(OverlordResource.java:221)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)


Does the "already present" message imply a problem?  I should add this is from a fresh start where no task ID of that name has ever existed, so it looks like an error but it can't be as the result of launching the task twice, etc.  Most output gets logged at "info" level so it's not always clear to me when something is a problem and when it is not.

If this is the result of some inherently bad data in the sample data file or in the batch config, might there be a more intelligible parsing of the data and/or the config, if there's something about it that is sure to fail?  Nothing about the data appears to be a problem, at least to me.

Thanks -- Wayne

[Gian Merlino]

There seems to be a casing bug floating around somewhere (the SegmentInsertAction is for datasource "smallcountexample" but the task is for datasource "smallCountExample"). Try changing your datasource to "smallcountexample" in the task json and see if that works.

[Wayne Adams]

Thanks, Gian!  That works!  -- Wayne