Kafka Indexing Service not working

hi guys,
I’m trying “Kafka Indexing Service” (version 0.9.1.1), and it does not work.

It seems AllocateSegmentAction which is a remote call from ‘task’ to ‘overlord’ fail again and again, and the task is stopped and started again

.

In overlord log, I can see something like below:

2016-07-14T12:39:23,487 INFO [qtp1522494105-153] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_kafka_test1_analyzer2.web_5d13bbec2501a66_iefcihpc]: SegmentAllocateAction{dataSource=‘test1_analyzer2.web’, timestamp=2016-07-14T12:36:27.000+08:00, queryGranularity=DurationGranularity{length=60000, origin=0}, preferredSegmentGranularity=DAY, sequenceName=‘index_kafka_test1_analyzer2.web_5d13bbec2501a66_3’, previousSegmentId=‘null’}

2016-07-14T12:39:23,491 WARN [qtp1522494105-153] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[test1_analyzer2.web], interval[2016-07-14T00:00:00.000+08:00/2016-07-15T00:00:00.000+08:00], maxVersion[2016-07-14T12:39:23.489+08:00]: conflicting segment[test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00].

2016-07-14T12:39:23,493 WARN [qtp1522494105-153] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[test1_analyzer2.web], interval[2016-07-14T12:00:00.000+08:00/2016-07-14T18:00:00.000+08:00], maxVersion[2016-07-14T12:39:23.489+08:00]: conflicting segment[test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00].

2016-07-14T12:39:23,494 WARN [qtp1522494105-153] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[test1_analyzer2.web], interval[2016-07-14T12:00:00.000+08:00/2016-07-14T13:00:00.000+08:00], maxVersion[2016-07-14T12:39:23.489+08:00]: conflicting segment[test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00].

2016-07-14T12:39:23,496 WARN [qtp1522494105-153] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[test1_analyzer2.web], interval[2016-07-14T12:30:00.000+08:00/2016-07-14T12:45:00.000+08:00], maxVersion[2016-07-14T12:39:23.489+08:00]: conflicting segment[test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00].

2016-07-14T12:39:23,498 WARN [qtp1522494105-153] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[test1_analyzer2.web], interval[2016-07-14T12:30:00.000+08:00/2016-07-14T12:40:00.000+08:00], maxVersion[2016-07-14T12:39:23.489+08:00]: conflicting segment[test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00].

2016-07-14T12:39:23,500 WARN [qtp1522494105-153] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[test1_analyzer2.web], interval[2016-07-14T12:35:00.000+08:00/2016-07-14T12:40:00.000+08:00], maxVersion[2016-07-14T12:39:23.489+08:00]: conflicting segment[test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00].

2016-07-14T12:39:23,502 WARN [qtp1522494105-153] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[test1_analyzer2.web], interval[2016-07-14T12:36:00.000+08:00/2016-07-14T12:37:00.000+08:00], maxVersion[2016-07-14T12:39:23.489+08:00]: conflicting segment[test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00].

2016-07-14T12:39:39,053 INFO [qtp1522494105-115] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_kafka_test1_analyzer2.web_5d13bbec2501a66_kckkgaak]: SegmentAllocateAction{dataSource=‘test1_analyzer2.web’, timestamp=2016-07-14T12:36:27.000+08:00, queryGranularity=DurationGranularity{length=60000, origin=0}, preferredSegmentGranularity=DAY, sequenceName=‘index_kafka_test1_analyzer2.web_5d13bbec2501a66_3’, previousSegmentId=‘null’}

2016-07-14T12:39:39,055 WARN [qtp1522494105-115] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[test1_analyzer2.web], interval[2016-07-14T00:00:00.000+08:00/2016-07-15T00:00:00.000+08:00], maxVersion[2016-07-14T12:39:39.054+08:00]: conflicting segment[test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00].

2016-07-14T12:39:39,057 WARN [qtp1522494105-115] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[test1_analyzer2.web], interval[2016-07-14T12:00:00.000+08:00/2016-07-14T18:00:00.000+08:00], maxVersion[2016-07-14T12:39:39.054+08:00]: conflicting segment[test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00].

2016-07-14T12:39:39,058 WARN [qtp1522494105-115] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[test1_analyzer2.web], interval[2016-07-14T12:00:00.000+08:00/2016-07-14T13:00:00.000+08:00], maxVersion[2016-07-14T12:39:39.054+08:00]: conflicting segment[test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00].

2016-07-14T12:39:39,060 WARN [qtp1522494105-115] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[test1_analyzer2.web], interval[2016-07-14T12:30:00.000+08:00/2016-07-14T12:45:00.000+08:00], maxVersion[2016-07-14T12:39:39.054+08:00]: conflicting segment[test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00].

2016-07-14T12:39:39,061 WARN [qtp1522494105-115] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[test1_analyzer2.web], interval[2016-07-14T12:30:00.000+08:00/2016-07-14T12:40:00.000+08:00], maxVersion[2016-07-14T12:39:39.054+08:00]: conflicting segment[test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00].

2016-07-14T12:39:39,062 WARN [qtp1522494105-115] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[test1_analyzer2.web], interval[2016-07-14T12:35:00.000+08:00/2016-07-14T12:40:00.000+08:00], maxVersion[2016-07-14T12:39:39.054+08:00]: conflicting segment[test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00].

2016-07-14T12:39:39,064 WARN [qtp1522494105-115] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[test1_analyzer2.web], interval[2016-07-14T12:36:00.000+08:00/2016-07-14T12:37:00.000+08:00], maxVersion[2016-07-14T12:39:39.054+08:00]: conflicting segment[test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00].

over and over again.

In middle manager I can see below:

2016-07-14T12:43:30,650 INFO [forking-task-runner-22] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_analyzer2.web_5d13bbec2501a66_meffcpok] status changed to [RUNNING].

2016-07-14T12:43:38,554 INFO [forking-task-runner-22] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_analyzer2.web_5d13bbec2501a66_meffcpok] status changed to [FAILED].

2016-07-14T12:43:38,572 INFO [forking-task-runner-23] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_analyzer2.web_5d13bbec2501a66_opbejkbj] location changed to [TaskLocation{host=‘hd020.corp.yodao.com’, port=8100}].

2016-07-14T12:43:38,572 INFO [forking-task-runner-23] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_analyzer2.web_5d13bbec2501a66_opbejkbj] status changed to [RUNNING].

2016-07-14T12:43:41,725 INFO [forking-task-runner-23] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_analyzer2.web_5d13bbec2501a66_opbejkbj] status changed to [FAILED].

2016-07-14T12:43:41,742 INFO [forking-task-runner-24] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_analyzer2.web_5d13bbec2501a66_iljdcgnb] location changed to [TaskLocation{host=‘hd020.corp.yodao.com’, port=8100}].

2016-07-14T12:43:41,742 INFO [forking-task-runner-24] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_analyzer2.web_5d13bbec2501a66_iljdcgnb] status changed to [RUNNING].

2016-07-14T12:43:46,455 INFO [forking-task-runner-25] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_analyzer2.web_5d13bbec2501a66_hkmiloml] location changed to [TaskLocation{host=‘hd020.corp.yodao.com’, port=8100}].

2016-07-14T12:43:46,455 INFO [forking-task-runner-25] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_analyzer2.web_5d13bbec2501a66_hkmiloml] status changed to [RUNNING].

2016-07-14T12:43:53,581 INFO [forking-task-runner-25] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_analyzer2.web_5d13bbec2501a66_hkmiloml] status changed to [FAILED].

2016-07-14T12:43:53,599 INFO [forking-task-runner-26] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_analyzer2.web_5d13bbec2501a66_mkalhfob] location changed to [TaskLocation{host=‘hd020.corp.yodao.com’, port=8100}].

over and over again.

In mysql, there are two lines in the table ‘druid_pendingSegments’ (in json):

[
{
"id":"test1_analyzer2.web_2016-07-12T00:00:00.000+08:00_2016-07-13T00:00:00.000+08:00_2016-07-14T00:06:29.619+08:00",
"dataSource":"test1_analyzer2.web",
"created_date":"2016-07-14T00:06:29.650+08:00",
"start":"2016-07-12T00:00:00.000+08:00",
"end":"2016-07-13T00:00:00.000+08:00",
"sequence_name":"index_kafka_test1_analyzer2.web_e7c4d4842d51c04_2",
"sequence_prev_id":"",
"payload":"{"dataSource":"test1_analyzer2.web","interval":"2016-07-12T00:00:00.000+08:00/2016-07-13T00:00:00.000+08:00","version":"2016-07-14T00:06:29.619+08:00","shardSpec":{"type":"numbered","partitionNum":0,"partitions":0}}",
"sequence_name_prev_id_sha1":"3602B2A5F8A3E47060C8FE4C70C0C65A95EA4A99"
},
{
"id":"test1_analyzer2.web_2016-07-14T00:00:00.000+08:00_2016-07-15T00:00:00.000+08:00_2016-07-14T11:47:50.363+08:00",
"dataSource":"test1_analyzer2.web",
"created_date":"2016-07-14T12:00:43.483+08:00",
"start":"2016-07-14T00:00:00.000+08:00",
"end":"2016-07-15T00:00:00.000+08:00",
"sequence_name":"index_kafka_test1_analyzer2.web_ab1048f7df801fb_2",
"sequence_prev_id":"",
"payload":"{"dataSource":"test1_analyzer2.web","interval":"2016-07-14T00:00:00.000+08:00/2016-07-15T00:00:00.000+08:00","version":"2016-07-14T11:47:50.363+08:00","shardSpec":{"type":"numbered","partitionNum":0,"partitions":0}}",
"sequence_name_prev_id_sha1":"D6D23B1B81683B3A10ECF1BD2349E9C29D2AC090"
}
]

Maybe this issue come from ‘sequence_name’ column?

When find a existing segment, it matches with ‘sequenec_name’ get empty set;

When creating new segment, it matches withou ‘sequence_name’ get one result. And conflicts.

How can I deal with this problem?

Any response is appreciated, thanks!

Problem solved.

I tried “-Duser.timezone=GMT+8” instead of “-Duser.timezone=Asia/Shanghai” for overlord.

It works.

In the IndexerSQLMetadataStorageCoordinator:

if (!max.getInterval().equals(interval) || max.getVersion().compareTo(maxVersion) > 0)

this “equals” do not evaluates to TRUE if one time zone is "FixedDateTimeZone " and another is “CachedDateTmieZone” although they are both GMT+08:00.

I think this is a bug, would you great developers fix this bug? :slight_smile:

在 2016年7月14日星期四 UTC+8下午12:50:38,李斯宁写道:

Hi, do you mind filing an issue for this?

filed @ https://github.com/druid-io/druid/issues/3256

在 2016年7月18日星期一 UTC+8上午1:47:23,Fangjin Yang写道: