ERROR "Merging when a merge isn't supposed to happen"

I run index service and submit a real time task, but when Panoramix refresh druid metadata, it throws error.

2015-09-23T11:34:49,971 ERROR [qtp1924255652-79] io.druid.server.QueryResource - Exception handling request: {class=io.druid.server.QueryResource, exceptionType=class com.metamx.common.ISE, exceptionMessage=Merging when a merge isn’t supposed to happen[SegmentAnalysis{id=‘sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00’, interval=[2015-09-23T11:00:00.000+08:00/2015-09-23T11:24:13.001+08:00], size=20944465}], [SegmentAnalysis{id=‘sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00’, interval=[2015-09-23T11:00:00.000+08:00/2015-09-23T11:20:35.001+08:00], size=20734244}], exception=com.metamx.common.ISE: Merging when a merge isn’t supposed to happen[SegmentAnalysis{id=‘sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00’, interval=[2015-09-23T11:00:00.000+08:00/2015-09-23T11:24:13.001+08:00], size=20944465}], [SegmentAnalysis{id=‘sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00’, interval=[2015-09-23T11:00:00.000+08:00/2015-09-23T11:20:35.001+08:00], size=20734244}], query=io.druid.query.metadata.metadata.SegmentMetadataQuery@947316ce, peer=10.183.168.1}

com.metamx.common.ISE: Merging when a merge isn’t supposed to happen[SegmentAnalysis{id=‘sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00’, interval=[2015-09-23T11:00:00.000+08:00/2015-09-23T11:24:13.001+08:00], size=20944465}], [SegmentAnalysis{id=‘sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00’, interval=[2015-09-23T11:00:00.000+08:00/2015-09-23T11:20:35.001+08:00], size=20734244}]

at io.druid.query.metadata.SegmentMetadataQueryQueryToolChest$2$2.apply(SegmentMetadataQueryQueryToolChest.java:103) ~[druid-processing-0.8.0.jar:0.8.0]

at io.druid.query.metadata.SegmentMetadataQueryQueryToolChest$2$2.apply(SegmentMetadataQueryQueryToolChest.java:88) ~[druid-processing-0.8.0.jar:0.8.0]

at io.druid.common.guava.CombiningSequence$CombiningYieldingAccumulator.accumulate(CombiningSequence.java:205) ~[druid-common-0.8.0.jar:0.8.0]

at com.metamx.common.guava.BaseSequence.makeYielder(BaseSequence.java:104) ~[java-util-0.27.0.jar:?]

at com.metamx.common.guava.BaseSequence.toYielder(BaseSequence.java:81) ~[java-util-0.27.0.jar:?]

at com.metamx.common.guava.ConcatSequence.makeYielder(ConcatSequence.java:93) ~[java-util-0.27.0.jar:?]

at com.metamx.common.guava.ConcatSequence.toYielder(ConcatSequence.java:72) ~[java-util-0.27.0.jar:?]

at io.druid.common.guava.CombiningSequence.toYielder(CombiningSequence.java:76) ~[druid-common-0.8.0.jar:0.8.0]

at com.metamx.common.guava.MappedSequence.toYielder(MappedSequence.java:46) ~[java-util-0.27.0.jar:?]

at io.druid.server.QueryResource.doPost(QueryResource.java:162) [druid-server-0.8.0.jar:0.8.0]

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.7.0_51]

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[?:1.7.0_51]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.7.0_51]

at java.lang.reflect.Method.invoke(Method.java:606) ~[?:1.7.0_51]

so why this happen, so how to solve it?

I grep the task’s log

2015-09-23T11:28:26,532 INFO [task-runner-0] io.druid.server.coordination.BatchDataSegmentAnnouncer - Announcing segment[sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00] at path[/druid/prod/segments/hadoop501.et2.tbsite.net:8100/hadoop501.et2.tbsite.net:8100_realtime__default_tier_2015-09-23T11:28:26.529+08:00_36a179730fea48aa91707f4539673b580]

2015-09-23T11:28:33,262 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00

2015-09-23T11:28:33,262 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00, numReferences: 0

2015-09-23T11:28:34,388 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00

2015-09-23T11:28:34,390 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00, numReferences: 0

2015-09-23T11:28:37,437 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00

2015-09-23T11:28:37,437 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00, numReferences: 0

2015-09-23T11:28:39,670 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00

2015-09-23T11:28:39,671 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00, numReferences: 0

2015-09-23T11:28:42,230 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00

2015-09-23T11:28:42,230 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00, numReferences: 0

2015-09-23T11:28:43,979 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00

2015-09-23T11:28:43,979 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00, numReferences: 0

2015-09-23T11:28:46,245 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00

2015-09-23T11:28:46,245 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00, numReferences: 0

2015-09-23T11:28:49,705 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00

2015-09-23T11:28:49,705 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00, numReferences: 0

2015-09-23T11:28:52,324 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00

2015-09-23T11:28:52,324 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00, numReferences: 0

2015-09-23T11:34:36,871 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00

2015-09-23T11:34:36,871 INFO [sync-incremental-persist] io.druid.segment.ReferenceCountingSegment - Closing sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00, numReferences: 0

com.metamx.common.ISE: Merging when a merge isn’t supposed to happen[SegmentAnalysis{id=‘sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00’, interval=[2015-09-23T11:00:00.000+08:00/2015-09-23T11:24:13.001+08:00], size=20944465}], [SegmentAnalysis{id=‘sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00’, interval=[2015-09-23T11:00:00.000+08:00/2015-09-23T11:20:35.001+08:00], size=20734244}]

2015-09-23T11:34:49,906 INFO [qtp1924255652-79] com.metamx.emitter.core.LoggingEmitter - Event [{“service”:“druid/prod/middlemanager”,“host”:“hadoop501.et2.tbsite.net:8100”,“feed”:“druid_requests”,“queryStats”:{“success”:false,“exception”:“com.metamx.common.ISE: Merging when a merge isn’t supposed to happen[SegmentAnalysis{id=‘sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00’, interval=[2015-09-23T11:00:00.000+08:00/2015-09-23T11:24:13.001+08:00], size=20944465}], [SegmentAnalysis{id=‘sync_2015-09-23T11:00:00.000+08:00_2015-09-23T12:00:00.000+08:00_2015-09-23T11:28:26.432+08:00’, interval=[2015-09-23T11:00:00.000+08:00/2015-09-23T11:20:35.001+08:00], size=20734244}]”},“timestamp”:“2015-09-23T11:34:49.900+08:00”,“remoteAddr”:“10.183.168.1”,“query”:{“queryType”:“segmentMetadata”,“dataSource”:{“type”:“table”,“name”:“sync”},“intervals”:{“type”:“segments”,“segments”:[{“itvl”:“2015-09-23T11:18:30.000+08:00/2015-09-23T11:18:32.000+08:00”,“ver”:“2015-09-23T11:28:26.432+08:00”,“part”:0}]},“toInclude”:{“type”:“all”},“merge”:false,“context”:{“finalize”:false,“queryId”:“a885e364-6e03-4074-8f68-52d3d6f695e2”,“timeout”:300000}}}]

so why this happen, so how to solve it? If only one can help?

Hey,

This is a bug in the SegmentMetadataQuery that is fixed in master and will be part of 0.8.2.

You can pull this PR for a quick fix:
https://github.com/druid-io/druid/pull/1739/files

Thanks very much for @Fangjin Yang @Gian Merlino