RabbitMQ realtime index task no results

So I have got a realtime index task running on my indexing service that consumes messages from RabbitMQ in realtime. The strange this is that Druid connects and consumes messages from RabbitMQ just fine, but messages are not acked/confirmed.

I can see this happening in my RabbitMQ console as all of the messages quickly move from the “Ready” state to “Unacked”. I am running the coordinator node, broker node, indexing service, and historic node and none of the logs indicate errors. I have attached my realtime index task spec file along with the relevant logs.

Any help is appreciated.

realtime.spec (1.65 KB)

broker.log (37.9 KB)

coordinator.log (67.1 KB)

historic.log (37.2 KB)

indexing.log (52.9 KB)

task.log (49.9 KB)

Attached a task log from another task run with more info.
2015-11-06T20:35:59,801 INFO [task-runner-0] io.druid.indexing.overlord.ThreadPoolTaskRunner - Running task: foo-task

2015-11-06T20:35:59,803 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Performing action for task[foo-task]: LockListAction{}

2015-11-06T20:35:59,817 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Submitting action for task[foo-task] to overlord[http://vagrant.vm:8090/druid/indexer/v1/action]: LockListAction{}

2015-11-06T20:35:59,835 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,880 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,881 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,881 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,881 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,882 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,883 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,883 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,883 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,884 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,884 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,885 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,885 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,886 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,886 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,887 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,887 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,888 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,889 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,889 INFO [task-runner-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:35:59,989 INFO [task-runner-0] io.druid.segment.realtime.plumber.RealtimePlumber - Creating plumber using rejectionPolicy[serverTime-PT10M]

2015-11-06T20:35:59,994 INFO [task-runner-0] io.druid.segment.realtime.plumber.RealtimePlumber - Expect to run at [2015-11-06T20:46:00.000Z]

2015-11-06T20:36:00,008 INFO [task-runner-0] io.druid.segment.realtime.plumber.RealtimePlumber - Starting merge and push.

2015-11-06T20:36:00,009 INFO [task-runner-0] io.druid.segment.realtime.plumber.RealtimePlumber - Found [0] segments. Attempting to hand off segments that start before [2015-11-06T20:26:00.000Z].

2015-11-06T20:36:00,009 INFO [task-runner-0] io.druid.segment.realtime.plumber.RealtimePlumber - Found [0] sinks to persist and merge

2015-11-06T20:36:00,031 INFO [task-runner-0] net.jodah.lyra.internal.ConnectionHandler - Creating connection cxn-1 to [localhost:5672]

2015-11-06T20:36:00,131 INFO [task-runner-0] net.jodah.lyra.internal.ConnectionHandler - Created connection cxn-1 to amqp://127.0.0.1:5672/

2015-11-06T20:36:00,156 INFO [task-runner-0] net.jodah.lyra.internal.ConnectionHandler - Created channel-1 on cxn-1

2015-11-06T20:36:00,168 INFO [task-runner-0] net.jodah.lyra.internal.ChannelHandler - Created consumer-amq.ctag-hkqC850XzS-pZNYqDCBV1Q of words via channel-1 on cxn-1

2015-11-06T20:36:22,959 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Performing action for task[foo-task]: LockAcquireAction{interval=2015-11-06T20:34:00.000Z/2015-11-06T20:35:00.000Z}

2015-11-06T20:36:22,962 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Submitting action for task[foo-task] to overlord[http://vagrant.vm:8090/druid/indexer/v1/action]: LockAcquireAction{interval=2015-11-06T20:34:00.000Z/2015-11-06T20:35:00.000Z}

2015-11-06T20:36:23,043 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Performing action for task[foo-task]: LockAcquireAction{interval=2015-11-06T20:34:00.000Z/2015-11-06T20:35:00.000Z}

2015-11-06T20:36:23,046 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Submitting action for task[foo-task] to overlord[http://vagrant.vm:8090/druid/indexer/v1/action]: LockAcquireAction{interval=2015-11-06T20:34:00.000Z/2015-11-06T20:35:00.000Z}

2015-11-06T20:36:23,100 INFO [task-runner-0] io.druid.server.coordination.BatchDataSegmentAnnouncer - Announcing segment[foo_2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z_2015-11-06T20:36:22.979Z] at path[/druid/segments/vagrant.vm:8100/vagrant.vm:8100_realtime__default_tier_2015-11-06T20:36:23.093Z_28acd2a8ff29467b9700de45b24671f80]

2015-11-06T20:36:50,760 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Performing action for task[foo-task]: LockAcquireAction{interval=2015-11-06T20:35:00.000Z/2015-11-06T20:36:00.000Z}

2015-11-06T20:36:50,762 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Submitting action for task[foo-task] to overlord[http://vagrant.vm:8090/druid/indexer/v1/action]: LockAcquireAction{interval=2015-11-06T20:35:00.000Z/2015-11-06T20:36:00.000Z}

2015-11-06T20:36:50,770 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Performing action for task[foo-task]: LockAcquireAction{interval=2015-11-06T20:35:00.000Z/2015-11-06T20:36:00.000Z}

2015-11-06T20:36:50,771 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Submitting action for task[foo-task] to overlord[http://vagrant.vm:8090/druid/indexer/v1/action]: LockAcquireAction{interval=2015-11-06T20:35:00.000Z/2015-11-06T20:36:00.000Z}

2015-11-06T20:36:50,811 INFO [task-runner-0] io.druid.server.coordination.BatchDataSegmentAnnouncer - Announcing segment[foo_2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z_2015-11-06T20:36:50.766Z] at path[/druid/segments/vagrant.vm:8100/vagrant.vm:8100_realtime__default_tier_2015-11-06T20:36:23.093Z_28acd2a8ff29467b9700de45b24671f80]

2015-11-06T20:46:00,005 INFO [foo-overseer-0] io.druid.segment.realtime.plumber.RealtimePlumber - Starting merge and push.

2015-11-06T20:46:00,005 INFO [foo-overseer-0] io.druid.segment.realtime.plumber.RealtimePlumber - Found [2] segments. Attempting to hand off segments that start before [2015-11-06T20:36:00.000Z].

2015-11-06T20:46:00,005 INFO [foo-overseer-0] io.druid.segment.realtime.plumber.RealtimePlumber - Adding entry [1446842040000=Sink{interval=2015-11-06T20:34:00.000Z/2015-11-06T20:35:00.000Z, schema=io.druid.segment.indexing.DataSchema@369d4c6f}] for merge and push.

2015-11-06T20:46:00,005 INFO [foo-overseer-0] io.druid.segment.realtime.plumber.RealtimePlumber - Adding entry [1446842100000=Sink{interval=2015-11-06T20:35:00.000Z/2015-11-06T20:36:00.000Z, schema=io.druid.segment.indexing.DataSchema@369d4c6f}] for merge and push.

2015-11-06T20:46:00,006 INFO [foo-overseer-0] io.druid.segment.realtime.plumber.RealtimePlumber - Found [2] sinks to persist and merge

2015-11-06T20:46:00,009 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.realtime.plumber.RealtimePlumber - Hydrant[FireHydrant{index=io.druid.segment.incremental.OnheapIncrementalIndex@52f56f3c, queryable=io.druid.segment.ReferenceCountingSegment@6f59f6b0, count=0}] hasn’t swapped yet, swapping. Sink[Sink{interval=2015-11-06T20:34:00.000Z/2015-11-06T20:35:00.000Z, schema=io.druid.segment.indexing.DataSchema@369d4c6f}]

2015-11-06T20:46:00,010 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.realtime.plumber.RealtimePlumber - DataSource[foo], Interval[2015-11-06T20:34:00.000Z/2015-11-06T20:35:00.000Z], persisting Hydrant[FireHydrant{index=io.druid.segment.incremental.OnheapIncrementalIndex@52f56f3c, queryable=io.druid.segment.ReferenceCountingSegment@6f59f6b0, count=0}]

2015-11-06T20:46:00,015 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.guice.PropertiesModule - Loading properties from common.runtime.properties

2015-11-06T20:46:00,015 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.guice.PropertiesModule - Loading properties from runtime.properties

2015-11-06T20:46:00,022 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - Starting persist for interval[2015-11-06T20:34:00.000Z/2015-11-06T20:35:00.000Z], rows[6,059]

2015-11-06T20:46:00,060 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/0/v8-tmp] completed index.drd in 5 millis.

2015-11-06T20:46:00,163 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/0/v8-tmp] completed dim conversions in 103 millis.

2015-11-06T20:46:00,363 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/0/v8-tmp] completed walk through of 6,059 rows in 200 millis.

2015-11-06T20:46:00,365 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - Starting dimension[word] with cardinality[6,059]

2015-11-06T20:46:00,571 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - Completed dimension[word] in 207 millis.

2015-11-06T20:46:00,571 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/0/v8-tmp] completed inverted.drd in 208 millis.

2015-11-06T20:46:00,579 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Converting v8[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/0/v8-tmp] to v9[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/0]

2015-11-06T20:46:00,581 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[dim_word.drd]

2015-11-06T20:46:00,590 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Dimension[word] is single value, converting…

2015-11-06T20:46:00,641 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[index.drd]

2015-11-06T20:46:00,642 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[inverted.drd]

2015-11-06T20:46:00,642 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[met_count_LITTLE_ENDIAN.drd]

2015-11-06T20:46:00,646 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[spatial.drd]

2015-11-06T20:46:00,646 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[time_LITTLE_ENDIAN.drd]

2015-11-06T20:46:00,649 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Skipped files[[index.drd, inverted.drd, spatial.drd]]

2015-11-06T20:46:00,681 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.ReferenceCountingSegment - Closing foo_2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z_2015-11-06T20:36:22.979Z

2015-11-06T20:46:00,681 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.ReferenceCountingSegment - Closing foo_2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z_2015-11-06T20:36:22.979Z, numReferences: 0

2015-11-06T20:46:00,681 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.realtime.plumber.RealtimePlumber - Adding hydrant[FireHydrant{index=null, queryable=io.druid.segment.ReferenceCountingSegment@40869efe, count=0}]

2015-11-06T20:46:00,689 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/merged/v8-tmp] completed index.drd in 1 millis.

2015-11-06T20:46:00,731 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/merged/v8-tmp] completed dim conversions in 42 millis.

2015-11-06T20:46:00,739 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.CompressedPools - Allocating new littleEndByteBuf[1]

2015-11-06T20:46:00,742 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.CompressedPools - Allocating new littleEndByteBuf[2]

2015-11-06T20:46:00,743 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.CompressedPools - Allocating new littleEndByteBuf[3]

2015-11-06T20:46:00,822 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/merged/v8-tmp] completed walk through of 6,059 rows in 91 millis.

2015-11-06T20:46:00,822 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - Starting dimension[word] with cardinality[6,059]

2015-11-06T20:46:01,131 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - Completed dimension[word] in 309 millis.

2015-11-06T20:46:01,131 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/merged/v8-tmp] completed inverted.drd in 309 millis.

2015-11-06T20:46:01,134 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Converting v8[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/merged/v8-tmp] to v9[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/merged]

2015-11-06T20:46:01,135 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[dim_word.drd]

2015-11-06T20:46:01,137 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Dimension[word] is single value, converting…

2015-11-06T20:46:01,141 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[index.drd]

2015-11-06T20:46:01,141 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[inverted.drd]

2015-11-06T20:46:01,141 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[met_count_LITTLE_ENDIAN.drd]

2015-11-06T20:46:01,142 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[spatial.drd]

2015-11-06T20:46:01,142 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[time_LITTLE_ENDIAN.drd]

2015-11-06T20:46:01,142 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Skipped files[[index.drd, inverted.drd, spatial.drd]]

2015-11-06T20:46:01,150 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.loading.LocalDataSegmentPusher - Copying segment[foo_2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z_2015-11-06T20:36:22.979Z] to local filesystem at location[/tmp/druid-indexing/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/2015-11-06T20:36:22.979Z/0]

2015-11-06T20:46:01,150 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.loading.LocalDataSegmentPusher - Compressing files from[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/merged] to [/tmp/druid-indexing/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/2015-11-06T20:36:22.979Z/0/index.zip]

2015-11-06T20:46:01,157 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] com.metamx.common.CompressionUtils - Adding file[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/merged/00000.smoosh] with size[215,331]. Total size so far[0]

2015-11-06T20:46:01,172 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] com.metamx.common.CompressionUtils - Adding file[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/merged/version.bin] with size[4]. Total size so far[215,331]

2015-11-06T20:46:01,173 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] com.metamx.common.CompressionUtils - Adding file[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/merged/meta.smoosh] with size[103]. Total size so far[215,335]

2015-11-06T20:46:01,175 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.segment.loading.LocalDataSegmentPusher - Creating descriptor file at[/tmp/druid-indexing/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/2015-11-06T20:36:22.979Z/0/descriptor.json]

2015-11-06T20:46:01,183 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.indexing.common.actions.RemoteTaskActionClient - Performing action for task[foo-task]: SegmentInsertAction{segments=[DataSegment{size=215438, shardSpec=NoneShardSpec, metrics=[count], dimensions=[word], version=‘2015-11-06T20:36:22.979Z’, loadSpec={type=local, path=/tmp/druid-indexing/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/2015-11-06T20:36:22.979Z/0/index.zip}, interval=2015-11-06T20:34:00.000Z/2015-11-06T20:35:00.000Z, dataSource=‘foo’, binaryVersion=‘9’}]}

2015-11-06T20:46:01,196 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] io.druid.indexing.common.actions.RemoteTaskActionClient - Submitting action for task[foo-task] to overlord[http://vagrant.vm:8090/druid/indexer/v1/action]: SegmentInsertAction{segments=[DataSegment{size=215438, shardSpec=NoneShardSpec, metrics=[count], dimensions=[word], version=‘2015-11-06T20:36:22.979Z’, loadSpec={type=local, path=/tmp/druid-indexing/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/2015-11-06T20:36:22.979Z/0/index.zip}, interval=2015-11-06T20:34:00.000Z/2015-11-06T20:35:00.000Z, dataSource=‘foo’, binaryVersion=‘9’}]}

2015-11-06T20:46:01,197 INFO [foo-2015-11-06T20:34:00.000Z-persist-n-merge] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:46:01,273 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.realtime.plumber.RealtimePlumber - Hydrant[FireHydrant{index=io.druid.segment.incremental.OnheapIncrementalIndex@475261fe, queryable=io.druid.segment.ReferenceCountingSegment@719f8f46, count=0}] hasn’t swapped yet, swapping. Sink[Sink{interval=2015-11-06T20:35:00.000Z/2015-11-06T20:36:00.000Z, schema=io.druid.segment.indexing.DataSchema@369d4c6f}]

2015-11-06T20:46:01,273 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.realtime.plumber.RealtimePlumber - DataSource[foo], Interval[2015-11-06T20:35:00.000Z/2015-11-06T20:36:00.000Z], persisting Hydrant[FireHydrant{index=io.druid.segment.incremental.OnheapIncrementalIndex@475261fe, queryable=io.druid.segment.ReferenceCountingSegment@719f8f46, count=0}]

2015-11-06T20:46:01,273 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - Starting persist for interval[2015-11-06T20:35:00.000Z/2015-11-06T20:36:00.000Z], rows[3,898]

2015-11-06T20:46:01,276 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/0/v8-tmp] completed index.drd in 0 millis.

2015-11-06T20:46:01,288 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/0/v8-tmp] completed dim conversions in 11 millis.

2015-11-06T20:46:01,337 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/0/v8-tmp] completed walk through of 3,898 rows in 41 millis.

2015-11-06T20:46:01,338 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - Starting dimension[word] with cardinality[3,898]

2015-11-06T20:46:01,379 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - Completed dimension[word] in 42 millis.

2015-11-06T20:46:01,379 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/0/v8-tmp] completed inverted.drd in 42 millis.

2015-11-06T20:46:01,390 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Converting v8[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/0/v8-tmp] to v9[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/0]

2015-11-06T20:46:01,390 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[dim_word.drd]

2015-11-06T20:46:01,391 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Dimension[word] is single value, converting…

2015-11-06T20:46:01,393 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[index.drd]

2015-11-06T20:46:01,393 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[inverted.drd]

2015-11-06T20:46:01,394 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[met_count_LITTLE_ENDIAN.drd]

2015-11-06T20:46:01,394 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[spatial.drd]

2015-11-06T20:46:01,394 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[time_LITTLE_ENDIAN.drd]

2015-11-06T20:46:01,394 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Skipped files[[index.drd, inverted.drd, spatial.drd]]

2015-11-06T20:46:01,396 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.ReferenceCountingSegment - Closing foo_2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z_2015-11-06T20:36:50.766Z

2015-11-06T20:46:01,396 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.ReferenceCountingSegment - Closing foo_2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z_2015-11-06T20:36:50.766Z, numReferences: 0

2015-11-06T20:46:01,396 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.realtime.plumber.RealtimePlumber - Adding hydrant[FireHydrant{index=null, queryable=io.druid.segment.ReferenceCountingSegment@7b7fccd4, count=0}]

2015-11-06T20:46:01,397 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/merged/v8-tmp] completed index.drd in 1 millis.

2015-11-06T20:46:01,401 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/merged/v8-tmp] completed dim conversions in 4 millis.

2015-11-06T20:46:01,413 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/merged/v8-tmp] completed walk through of 3,898 rows in 12 millis.

2015-11-06T20:46:01,414 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - Starting dimension[word] with cardinality[3,898]

2015-11-06T20:46:01,445 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - Completed dimension[word] in 31 millis.

2015-11-06T20:46:01,445 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexMerger - outDir[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/merged/v8-tmp] completed inverted.drd in 31 millis.

2015-11-06T20:46:01,447 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Converting v8[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/merged/v8-tmp] to v9[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/merged]

2015-11-06T20:46:01,448 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[dim_word.drd]

2015-11-06T20:46:01,449 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Dimension[word] is single value, converting…

2015-11-06T20:46:01,450 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[index.drd]

2015-11-06T20:46:01,450 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[inverted.drd]

2015-11-06T20:46:01,450 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[met_count_LITTLE_ENDIAN.drd]

2015-11-06T20:46:01,451 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[spatial.drd]

2015-11-06T20:46:01,451 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Processing file[time_LITTLE_ENDIAN.drd]

2015-11-06T20:46:01,451 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.IndexIO$DefaultIndexIOHandler - Skipped files[[index.drd, inverted.drd, spatial.drd]]

2015-11-06T20:46:01,455 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.loading.LocalDataSegmentPusher - Copying segment[foo_2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z_2015-11-06T20:36:50.766Z] to local filesystem at location[/tmp/druid-indexing/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/2015-11-06T20:36:50.766Z/0]

2015-11-06T20:46:01,456 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.loading.LocalDataSegmentPusher - Compressing files from[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/merged] to [/tmp/druid-indexing/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/2015-11-06T20:36:50.766Z/0/index.zip]

2015-11-06T20:46:01,456 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] com.metamx.common.CompressionUtils - Adding file[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/merged/00000.smoosh] with size[138,063]. Total size so far[0]

2015-11-06T20:46:01,466 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] com.metamx.common.CompressionUtils - Adding file[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/merged/version.bin] with size[4]. Total size so far[138,063]

2015-11-06T20:46:01,467 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] com.metamx.common.CompressionUtils - Adding file[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/merged/meta.smoosh] with size[103]. Total size so far[138,067]

2015-11-06T20:46:01,469 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.segment.loading.LocalDataSegmentPusher - Creating descriptor file at[/tmp/druid-indexing/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/2015-11-06T20:36:50.766Z/0/descriptor.json]

2015-11-06T20:46:01,469 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.indexing.common.actions.RemoteTaskActionClient - Performing action for task[foo-task]: SegmentInsertAction{segments=[DataSegment{size=138170, shardSpec=NoneShardSpec, metrics=[count], dimensions=[word], version=‘2015-11-06T20:36:50.766Z’, loadSpec={type=local, path=/tmp/druid-indexing/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/2015-11-06T20:36:50.766Z/0/index.zip}, interval=2015-11-06T20:35:00.000Z/2015-11-06T20:36:00.000Z, dataSource=‘foo’, binaryVersion=‘9’}]}

2015-11-06T20:46:01,470 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] io.druid.indexing.common.actions.RemoteTaskActionClient - Submitting action for task[foo-task] to overlord[http://vagrant.vm:8090/druid/indexer/v1/action]: SegmentInsertAction{segments=[DataSegment{size=138170, shardSpec=NoneShardSpec, metrics=[count], dimensions=[word], version=‘2015-11-06T20:36:50.766Z’, loadSpec={type=local, path=/tmp/druid-indexing/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/2015-11-06T20:36:50.766Z/0/index.zip}, interval=2015-11-06T20:35:00.000Z/2015-11-06T20:36:00.000Z, dataSource=‘foo’, binaryVersion=‘9’}]}

2015-11-06T20:46:01,470 INFO [foo-2015-11-06T20:35:00.000Z-persist-n-merge] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:46:30,527 INFO [plumber_merge_0] io.druid.segment.realtime.plumber.RealtimePlumber - Segment[DataSegment{size=138170, shardSpec=NoneShardSpec, metrics=[count], dimensions=[word], version=‘2015-11-06T20:36:50.766Z’, loadSpec={type=local, path=/tmp/druid-indexing/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z/2015-11-06T20:36:50.766Z/0/index.zip}, interval=2015-11-06T20:35:00.000Z/2015-11-06T20:36:00.000Z, dataSource=‘foo’, binaryVersion=‘9’}] matches sink[Sink{interval=2015-11-06T20:35:00.000Z/2015-11-06T20:36:00.000Z, schema=io.druid.segment.indexing.DataSchema@369d4c6f}] on server[DruidServerMetadata{name=‘vagrant.vm:8083’, host=‘vagrant.vm:8083’, maxSize=10000000000, tier=’_default_tier’, type=‘historical’, priority=‘0’}]

2015-11-06T20:46:30,527 INFO [plumber_merge_0] io.druid.segment.realtime.plumber.RealtimePlumber - Segment version[2015-11-06T20:36:50.766Z] >= sink version[2015-11-06T20:36:50.766Z]

2015-11-06T20:46:30,528 INFO [plumber_merge_0] io.druid.server.coordination.BatchDataSegmentAnnouncer - Unannouncing segment[foo_2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z_2015-11-06T20:36:50.766Z] at path[/druid/segments/vagrant.vm:8100/vagrant.vm:8100_realtime__default_tier_2015-11-06T20:36:23.093Z_28acd2a8ff29467b9700de45b24671f80]

2015-11-06T20:46:30,529 INFO [plumber_merge_0] io.druid.indexing.common.actions.RemoteTaskActionClient - Performing action for task[foo-task]: LockReleaseAction{interval=2015-11-06T20:35:00.000Z/2015-11-06T20:36:00.000Z}

2015-11-06T20:46:30,531 INFO [plumber_merge_0] io.druid.indexing.common.actions.RemoteTaskActionClient - Submitting action for task[foo-task] to overlord[http://vagrant.vm:8090/druid/indexer/v1/action]: LockReleaseAction{interval=2015-11-06T20:35:00.000Z/2015-11-06T20:36:00.000Z}

2015-11-06T20:46:30,531 INFO [plumber_merge_0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:46:30,554 INFO [plumber_merge_0] io.druid.segment.realtime.plumber.RealtimePlumber - Deleting Index File[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z]

2015-11-06T20:46:30,556 INFO [plumber_merge_0] io.druid.segment.realtime.plumber.RealtimePlumber - Removing sinkKey 1446842100000 for segment foo_2015-11-06T20:35:00.000Z_2015-11-06T20:36:00.000Z_2015-11-06T20:36:50.766Z

2015-11-06T20:46:30,581 INFO [plumber_merge_0] io.druid.segment.realtime.plumber.RealtimePlumber - Segment[DataSegment{size=215438, shardSpec=NoneShardSpec, metrics=[count], dimensions=[word], version=‘2015-11-06T20:36:22.979Z’, loadSpec={type=local, path=/tmp/druid-indexing/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z/2015-11-06T20:36:22.979Z/0/index.zip}, interval=2015-11-06T20:34:00.000Z/2015-11-06T20:35:00.000Z, dataSource=‘foo’, binaryVersion=‘9’}] matches sink[Sink{interval=2015-11-06T20:34:00.000Z/2015-11-06T20:35:00.000Z, schema=io.druid.segment.indexing.DataSchema@369d4c6f}] on server[DruidServerMetadata{name=‘vagrant.vm:8083’, host=‘vagrant.vm:8083’, maxSize=10000000000, tier=’_default_tier’, type=‘historical’, priority=‘0’}]

2015-11-06T20:46:30,582 INFO [plumber_merge_0] io.druid.segment.realtime.plumber.RealtimePlumber - Segment version[2015-11-06T20:36:22.979Z] >= sink version[2015-11-06T20:36:22.979Z]

2015-11-06T20:46:30,582 INFO [plumber_merge_0] io.druid.server.coordination.BatchDataSegmentAnnouncer - Unannouncing segment[foo_2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z_2015-11-06T20:36:22.979Z] at path[/druid/segments/vagrant.vm:8100/vagrant.vm:8100_realtime__default_tier_2015-11-06T20:36:23.093Z_28acd2a8ff29467b9700de45b24671f80]

2015-11-06T20:46:30,583 INFO [plumber_merge_0] io.druid.curator.announcement.Announcer - unannouncing [/druid/segments/vagrant.vm:8100/vagrant.vm:8100_realtime__default_tier_2015-11-06T20:36:23.093Z_28acd2a8ff29467b9700de45b24671f80]

2015-11-06T20:46:30,602 INFO [plumber_merge_0] io.druid.indexing.common.actions.RemoteTaskActionClient - Performing action for task[foo-task]: LockReleaseAction{interval=2015-11-06T20:34:00.000Z/2015-11-06T20:35:00.000Z}

2015-11-06T20:46:30,603 INFO [plumber_merge_0] io.druid.indexing.common.actions.RemoteTaskActionClient - Submitting action for task[foo-task] to overlord[http://vagrant.vm:8090/druid/indexer/v1/action]: LockReleaseAction{interval=2015-11-06T20:34:00.000Z/2015-11-06T20:35:00.000Z}

2015-11-06T20:46:30,604 INFO [plumber_merge_0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://vagrant.vm:8090

2015-11-06T20:46:30,618 INFO [plumber_merge_0] io.druid.segment.realtime.plumber.RealtimePlumber - Deleting Index File[/tmp/persistent/task/foo-task/work/persist/foo/2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z]

2015-11-06T20:46:30,619 INFO [plumber_merge_0] io.druid.segment.realtime.plumber.RealtimePlumber - Removing sinkKey 1446842040000 for segment foo_2015-11-06T20:34:00.000Z_2015-11-06T20:35:00.000Z_2015-11-06T20:36:22.979Z

2015-11-06T20:47:00,010 INFO [foo-overseer-0] io.druid.segment.realtime.plumber.RealtimePlumber - Starting merge and push.

2015-11-06T20:47:00,010 INFO [foo-overseer-0] io.druid.segment.realtime.plumber.RealtimePlumber - Found [0] segments. Attempting to hand off segments that start before [2015-11-06T20:37:00.000Z].

2015-11-06T20:47:00,010 INFO [foo-overseer-0] io.druid.segment.realtime.plumber.RealtimePlumber - Found [0] sinks to persist and merge

2015-11-06T20:48:00,010 INFO [foo-overseer-0] io.druid.segment.realtime.plumber.RealtimePlumber - Starting merge and push.

``

Hey Andrei,

The RabbitMQ Firehose in Druid acks messages when it persists to disk. This happens when it processes a maxRowsInMemory number of messages, or when an intermediatePersistPeriod amount of time has passed, whichever comes first.

So some things to look at:

  • Are any of your messages actually getting processed? They might be getting dropped if they are too old (< windowPeriod) or unparseable. If all your messages are getting dropped, there will be nothing to persist, and so Druid will never ack anything. You can see metrics on events processed and dropped if you enable emitting metrics (see http://druid.io/docs/latest/configuration/index.html and http://druid.io/docs/latest/operations/metrics.html). You can also try doing some test queries (timeBoundary is a good one) to see if there is any data in the datasource.

  • If messages are getting processed, have any persists happened yet? You may have to wait for more messages to be processed, or for your intermediatePersistPeriod to elapse.