Hi Jesse,
thanks for posting the detailed log messages. We've created a bug report on
GitHub for this issue. Please subscribe to
https://github.com/Graylog2/graylog2-server/issues/1465 to get updates on
the issue.
Cheers,
Jochen
On Monday, 5 October 2015 17:10:43 UTC+2, Jesse Skrivseth wrote:
>
> Hey Jochen,
>
> Yes, I had to manually trigger the index range rebuild. Note that if you
> make an API call to /system/indexer/indices/{index}/close it also triggers
> a recalc across all indices. Since concurrent range recalcs are not
> possible, that means in our system if you make an API call to close an
> index, you have to wait 2.5 hours to try to close another. I see warnings
> like this frequently:
>
> 2015-10-05_14:47:03.98401 WARN [EsIndexRangeService] Couldn't load index
> range for index graylog_4128
> 2015-10-05_14:47:03.99521 WARN [EsIndexRangeService] Couldn't load index
> range for index graylog_4132
> 2015-10-05_14:47:05.33256 WARN [EsIndexRangeService] Couldn't load index
> range for index graylog_4135
> 2015-10-05_14:47:05.33283 WARN [EsIndexRangeService] Couldn't load index
> range for index graylog_4136
> 2015-10-05_14:48:02.03805 WARN [EsIndexRangeService] Couldn't load index
> range for index graylog_4128
> 2015-10-05_14:48:02.03828 WARN [EsIndexRangeService] Couldn't load index
> range for index graylog_4132
>
> Since the System->Indices page won't load, I manually made a call
> to /system/indices/ranges/rebuild to trigger it. After several hours, it
> eventually finds the problematic indices and throws these exceptions:
>
> 2015-10-05_03:03:58.03817 INFO [EsIndexRangeService] Calculated range of
> [graylog_3282] in [58ms].
> 2015-10-05_03:04:01.05886 INFO [EsIndexRangeService] Calculated range of
> [graylog_3281] in [146ms].
> 2015-10-05_03:04:05.29949 INFO [EsIndexRangeService] Calculated range of
> [graylog_3288] in [57ms].
> 2015-10-05_03:04:08.30944 ERROR [EsIndexRangeService] Error while
> calculating timestamp stats in index <graylog_4136>
> 2015-10-05_03:04:08.30947
> org.elasticsearch.action.search.SearchPhaseExecutionException: Failed to
> execute phase [query], all shards failed; shardFailures
> {[hPjzunuIQHivOLVhGMugsg][graylog_4136][0]:
> RemoteTransportException[[Cethlann][inet[/x.x.x.x:9300]][indices:data/read/search[phase/query]]];
>
> nested:
> ClassCastException[org.elasticsearch.index.fielddata.plain.PagedBytesIndexFieldData
>
> cannot be cast to org.elasticsearch.index.fielddata.IndexNumericFieldData];
> }{[2lLV-RaMTUWwl74xETQ8HA][graylog_4136][1]:
> RemoteTransportException[[Unseen][inet[/x.x.x.x:9300]][indices:data/read/search[phase/query]]];
>
> nested:
> ClassCastException[org.elasticsearch.index.fielddata.plain.PagedBytesIndexFieldData
>
> cannot be cast to org.elasticsearch.index.fielddata.IndexNumericFieldData];
> }{[2lLV-RaMTUWwl74xETQ8HA][graylog_4136][2]:
> RemoteTransportException[[Unseen][inet[/x.x.x.x:9300]][indices:data/read/search[phase/query]]];
>
> nested:
> ClassCastException[org.elasticsearch.index.fielddata.plain.PagedBytesIndexFieldData
>
> cannot be cast to org.elasticsearch.index.fielddata.IndexNumericFieldData];
> }{[hPjzunuIQHivOLVhGMugsg][graylog_4136][3]:
> RemoteTransportException[[Cethlann][inet[/x.x.x.x:9300]][indices:data/read/search[phase/query]]];
>
> nested:
> ClassCastException[org.elasticsearch.index.fielddata.plain.PagedBytesIndexFieldData
>
> cannot be cast to org.elasticsearch.index.fielddata.IndexNumericFieldData];
> }
> 2015-10-05_03:04:08.30951 at
> org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction.onFirstPhaseResult(TransportSearchTypeAction.java:237)
> 2015-10-05_03:04:08.30951 at
> org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction$1.onFailure(TransportSearchTypeAction.java:183)
> 2015-10-05_03:04:08.30951 at
> org.elasticsearch.search.action.SearchServiceTransportAction$6.handleException(SearchServiceTransportAction.java:249)
> 2015-10-05_03:04:08.30952 at
> org.elasticsearch.transport.netty.MessageChannelHandler.handleException(MessageChannelHandler.java:190)
> 2015-10-05_03:04:08.30952 at
> org.elasticsearch.transport.netty.MessageChannelHandler.handlerResponseError(MessageChannelHandler.java:180)
> 2015-10-05_03:04:08.30953 at
> org.elasticsearch.transport.netty.MessageChannelHandler.messageReceived(MessageChannelHandler.java:130)
> 2015-10-05_03:04:08.30953 at
> org.elasticsearch.common.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
> 2015-10-05_03:04:08.30954 at
> org.elasticsearch.common.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
> 2015-10-05_03:04:08.30954 at
> org.elasticsearch.common.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
> 2015-10-05_03:04:08.30955 at
> org.elasticsearch.common.netty.channel.Channels.fireMessageReceived(Channels.java:296)
> 2015-10-05_03:04:08.30955 at
> org.elasticsearch.common.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:462)
> 2015-10-05_03:04:08.30956 at
> org.elasticsearch.common.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:443)
> 2015-10-05_03:04:08.30956 at
> org.elasticsearch.common.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:303)
> 2015-10-05_03:04:08.30956 at
> org.elasticsearch.common.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
> 2015-10-05_03:04:08.30957 at
> org.elasticsearch.common.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
> 2015-10-05_03:04:08.30958 at
> org.elasticsearch.common.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559)
> 2015-10-05_03:04:08.30958 at
> org.elasticsearch.common.netty.channel.Channels.fireMessageReceived(Channels.java:268)
> 2015-10-05_03:04:08.30958 at
> org.elasticsearch.common.netty.channel.Channels.fireMessageReceived(Channels.java:255)
> 2015-10-05_03:04:08.30959 at
> org.elasticsearch.common.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88)
> 2015-10-05_03:04:08.30959 at
> org.elasticsearch.common.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108)
> 2015-10-05_03:04:08.30960 at
> org.elasticsearch.common.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)
> 2015-10-05_03:04:08.30961 at
> org.elasticsearch.common.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89)
> 2015-10-05_03:04:08.30961 at
> org.elasticsearch.common.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)
> 2015-10-05_03:04:08.30961 at
> org.elasticsearch.common.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
> 2015-10-05_03:04:08.30962 at
> org.elasticsearch.common.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
> 2015-10-05_03:04:08.30963 at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> 2015-10-05_03:04:08.30963 at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> 2015-10-05_03:04:08.30964 at java.lang.Thread.run(Thread.java:745)
> 2015-10-05_03:04:08.31020 INFO [RebuildIndexRangesJob] Could not
> calculate range of index [graylog_4136]. Skipping.
> 2015-10-05_03:04:08.31022 org.elasticsearch.indices.IndexMissingException:
> [graylog_4136] missing
> 2015-10-05_03:04:08.31022 at
> org.graylog2.indexer.ranges.EsIndexRangeService.timestampStatsOfIndex(EsIndexRangeService.java:249)
> 2015-10-05_03:04:08.31022 at
> org.graylog2.indexer.ranges.EsIndexRangeService.calculateRange(EsIndexRangeService.java:217)
> 2015-10-05_03:04:08.31023 at
> org.graylog2.indexer.ranges.RebuildIndexRangesJob.execute(RebuildIndexRangesJob.java:96)
> 2015-10-05_03:04:08.31023 at
> org.graylog2.system.jobs.SystemJobManager$1.run(SystemJobManager.java:88)
> 2015-10-05_03:04:08.31024 at
> com.codahale.metrics.InstrumentedScheduledExecutorService$InstrumentedRunnable.run(InstrumentedScheduledExecutorService.java:235)
> 2015-10-05_03:04:08.31024 at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> 2015-10-05_03:04:08.31024 at
> java.util.concurrent.FutureTask.run(FutureTask.java:266)
> 2015-10-05_03:04:08.31025 at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
> 2015-10-05_03:04:08.31025 at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
> 2015-10-05_03:04:08.31026 at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> 2015-10-05_03:04:08.31027 at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> 2015-10-05_03:04:08.31027 at java.lang.Thread.run(Thread.java:745)
> 2015-10-05_03:04:08.38399 INFO [EsIndexRangeService] Calculated range of
> [graylog_3287] in [73ms].
> 2015-10-05_03:04:11.52658 INFO [EsIndexRangeService] Calculated range of
> [graylog_4137] in [42ms].
>
> So unfortunately, those indices never have valid ranges due to the
> exception.
>
> The range recalc seems to have trouble with "index missing" exceptions,
> probably due to ES throwing other exceptions related to that index. The
> index is not missing.
>
>
> 2015-10-05_14:37:02.99050 WARN [EsIndexRangeService] Couldn't load index
> range for index graylog_4128
> 2015-10-05_14:37:02.99091 WARN [EsIndexRangeService] Couldn't load index
> range for index graylog_4136
> 2015-10-05_14:37:02.99214 WARN [EsIndexRangeService] Couldn't load index
> range for index graylog_4293
> 2015-10-05_14:37:17.78183 INFO [SetIndexReadOnlyJob] Flushing old index
> <graylog_4292>.
> 2015-10-05_14:37:18.30641 INFO [SetIndexReadOnlyJob] Setting old index
> <graylog_4292> to read-only.
> 2015-10-05_14:37:21.84393 INFO [SystemJobManager] Submitted SystemJob
> <9664c833-6b6e-11e5-b272-0ae24e7f4757>
> [org.graylog2.indexer.indices.jobs.OptimizeIndexJob]
> 2015-10-05_14:37:21.84397 INFO [SystemJobManager] SystemJob
> <82175553-6b6e-11e5-b272-0ae24e7f4757>
> [org.graylog2.indexer.SetIndexReadOnlyJob] finished in 4062ms.
> 2015-10-05_14:37:21.84419 INFO [OptimizeIndexJob] Optimizing index
> <graylog_4292>.
> 2015-10-05_14:37:31.82487 WARN [EsIndexRangeService] Couldn't load index
> range for index graylog_4128
> 2015-10-05_14:37:31.82519 WARN [EsIndexRangeService] Couldn't load index
> range for index graylog_4136
> 2015-10-05_14:37:31.82658 WARN [EsIndexRangeService] Couldn't load index
> range for index graylog_4293
> 2015-10-05_14:37:31.83269 WARN [IndexHelper] Couldn't find latest
> deflector target index
> 2015-10-05_14:37:31.83270 org.graylog2.database.NotFoundException:
> Couldn't find index range for index graylog_4293
> 2015-10-05_14:37:31.83271 at
> org.graylog2.indexer.ranges.EsIndexRangeService.loadIndexRange(EsIndexRangeService.java:156)
> 2015-10-05_14:37:31.83271 at
> org.graylog2.indexer.ranges.EsIndexRangeService.access$000(EsIndexRangeService.java:79)
> 2015-10-05_14:37:31.83271 at
> org.graylog2.indexer.ranges.EsIndexRangeService$1.load(EsIndexRangeService.java:107)
> 2015-10-05_14:37:31.83272 at
> org.graylog2.indexer.ranges.EsIndexRangeService$1.load(EsIndexRangeService.java:104)
> 2015-10-05_14:37:31.83272 at
> com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3527)
> 2015-10-05_14:37:31.83272 at
> com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2319)
> 2015-10-05_14:37:31.83273 at
> com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2282)
> 2015-10-05_14:37:31.83273 at
> com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2197)
> 2015-10-05_14:37:31.83273 at
> com.google.common.cache.LocalCache.get(LocalCache.java:3937)
> 2015-10-05_14:37:31.83273 at
> com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3941)
> 2015-10-05_14:37:31.83274 at
> com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4824)
> 2015-10-05_14:37:31.83274 at
> org.graylog2.indexer.ranges.EsIndexRangeService.get(EsIndexRangeService.java:131)
> 2015-10-05_14:37:31.83274 at
> org.graylog2.indexer.IndexHelper.determineAffectedIndicesWithRanges(IndexHelper.java:119)
> 2015-10-05_14:37:31.83275 at
> org.graylog2.indexer.searches.Searches.search(Searches.java:241)
> 2015-10-05_14:37:31.83275 at
> org.graylog2.rest.resources.search.RelativeSearchResource.searchRelative(RelativeSearchResource.java:103)
> 2015-10-05_14:37:31.83275 at
> sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> 2015-10-05_14:37:31.83276 at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> 2015-10-05_14:37:31.83277 at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 2015-10-05_14:37:31.83277 at
> java.lang.reflect.Method.invoke(Method.java:497)
> 2015-10-05_14:37:31.83277 at
> org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
> 2015-10-05_14:37:31.83277 at
> org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)
> 2015-10-05_14:37:31.83278 at
> org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)
> 2015-10-05_14:37:31.83278 at
> org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:205)
> 2015-10-05_14:37:31.83278 at
> org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)
> 2015-10-05_14:37:31.83278 at
> org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)
> 2015-10-05_14:37:31.83279 at
> org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)
> 2015-10-05_14:37:31.83279 at
> org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)
> 2015-10-05_14:37:31.83279 at
> org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:308)
> 2015-10-05_14:37:31.83279 at
> org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
> 2015-10-05_14:37:31.83280 at
> org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
> 2015-10-05_14:37:31.83280 at
> org.glassfish.jersey.internal.Errors.process(Errors.java:315)
> 2015-10-05_14:37:31.83280 at
> org.glassfish.jersey.internal.Errors.process(Errors.java:297)
> 2015-10-05_14:37:31.83280 at
> org.glassfish.jersey.internal.Errors.process(Errors.java:267)
> 2015-10-05_14:37:31.83281 at
> org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
> 2015-10-05_14:37:31.83281 at
> org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:291)
> 2015-10-05_14:37:31.83281 at
> org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1140)
> 2015-10-05_14:37:31.83281 at
> org.graylog2.jersey.container.netty.NettyContainer.messageReceived(NettyContainer.java:356)
> 2015-10-05_14:37:31.83281 at
> org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
> 2015-10-05_14:37:31.83282 at
> org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
> 2015-10-05_14:37:31.83283 at
> org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
> 2015-10-05_14:37:31.83283 at
> org.jboss.netty.handler.execution.ChannelUpstreamEventRunnable.doRun(ChannelUpstreamEventRunnable.java:43)
> 2015-10-05_14:37:31.83283 at
> org.jboss.netty.handler.execution.ChannelEventRunnable.run(ChannelEventRunnable.java:67)
> 2015-10-05_14:37:31.83284 at
> com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
> 2015-10-05_14:37:31.83284 at
> org.jboss.netty.handler.execution.MemoryAwareThreadPoolExecutor$MemoryAwareRunnable.run(MemoryAwareThreadPoolExecutor.java:606)
> 2015-10-05_14:37:31.83284 at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> 2015-10-05_14:37:31.83285 at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> 2015-10-05_14:37:31.83285 at java.lang.Thread.run(Thread.java:745)
> 2015-10-05_14:37:34.54268 ERROR [AnyExceptionClassMapper] Unhandled
> exception in REST resource
> 2015-10-05_14:37:34.54272 org.elasticsearch.ElasticsearchTimeoutException:
> Timeout waiting for task.
> 2015-10-05_14:37:34.54273 at
> org.elasticsearch.action.support.AdapterActionFuture.actionGet(AdapterActionFuture.java:73)
> 2015-10-05_14:37:34.54274 at
> org.graylog2.indexer.elasticsearch.GlobalTimeoutClient$GlobalTimeoutActionFuture.actionGet(GlobalTimeoutClient.java:150)
> 2015-10-05_14:37:34.54274 at
> org.graylog2.indexer.searches.Searches.histogram(Searches.java:467)
> 2015-10-05_14:37:34.54275 at
> org.graylog2.rest.resources.search.RelativeSearchResource.histogramRelative(RelativeSearchResource.java:251)
> 2015-10-05_14:37:34.54275 at
> sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> 2015-10-05_14:37:34.54275 at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> 2015-10-05_14:37:34.54276 at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 2015-10-05_14:37:34.54277 at
> java.lang.reflect.Method.invoke(Method.java:497)
> 2015-10-05_14:37:34.54278 at
> org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
> 2015-10-05_14:37:34.54279 at
> org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)
> 2015-10-05_14:37:34.54280 at
> org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)
> 2015-10-05_14:37:34.54280 at
> org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:205)
> 2015-10-05_14:37:34.54280 at
> org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)
> 2015-10-05_14:37:34.54281 at
> org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)
> 2015-10-05_14:37:34.54281 at
> org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)
> 2015-10-05_14:37:34.54281 at
> org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)
> 2015-10-05_14:37:34.54282 at
> org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:308)
> 2015-10-05_14:37:34.54282 at
> org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
> 2015-10-05_14:37:34.54282 at
> org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
> 2015-10-05_14:37:34.54283 at
> org.glassfish.jersey.internal.Errors.process(Errors.java:315)
> 2015-10-05_14:37:34.54283 at
> org.glassfish.jersey.internal.Errors.process(Errors.java:297)
> 2015-10-05_14:37:34.54285 at
> org.glassfish.jersey.internal.Errors.process(Errors.java:267)
> 2015-10-05_14:37:34.54285 at
> org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
> 2015-10-05_14:37:34.54286 at
> org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:291)
> 2015-10-05_14:37:34.54286 at
> org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1140)
> 2015-10-05_14:37:34.54286 at
> org.graylog2.jersey.container.netty.NettyContainer.messageReceived(NettyContainer.java:356)
> 2015-10-05_14:37:34.54287 at
> org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
> 2015-10-05_14:37:34.54287 at
> org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
> 2015-10-05_14:37:34.54287 at
> org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
> 2015-10-05_14:37:34.54288 at
> org.jboss.netty.handler.execution.ChannelUpstreamEventRunnable.doRun(ChannelUpstreamEventRunnable.java:43)
> 2015-10-05_14:37:34.54288 at
> org.jboss.netty.handler.execution.ChannelEventRunnable.run(ChannelEventRunnable.java:67)
> 2015-10-05_14:37:34.54289 at
> com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
> 2015-10-05_14:37:34.54289 at
> org.jboss.netty.handler.execution.MemoryAwareThreadPoolExecutor$MemoryAwareRunnable.run(MemoryAwareThreadPoolExecutor.java:606)
> 2015-10-05_14:37:34.54289 at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> 2015-10-05_14:37:34.54294 at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> 2015-10-05_14:37:34.54295 at java.lang.Thread.run(Thread.java:745)
> 2015-10-05_14:37:34.66572 ERROR [AnyExceptionClassMapper] Unhandled
> exception in REST resource
> 2015-10-05_14:37:34.66574
> com.google.common.util.concurrent.UncheckedExecutionException:
> org.elasticsearch.ElasticsearchTimeoutException: Timeout waiting for task.
> 2015-10-05_14:37:34.66575 at
> com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2203)
> 2015-10-05_14:37:34.66575 at
> com.google.common.cache.LocalCache.get(LocalCache.java:3937)
> 2015-10-05_14:37:34.66576 at
> com.google.common.cache.LocalCache$LocalManualCache.get(LocalCache.java:4739)
> 2015-10-05_14:37:34.66576 at
> org.graylog2.rest.resources.sources.SourcesResource.list(SourcesResource.java:89)
> 2015-10-05_14:37:34.66577 at
> sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> 2015-10-05_14:37:34.66578 at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> 2015-10-05_14:37:34.66578 at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 2015-10-05_14:37:34.66579 at
> java.lang.reflect.Method.invoke(Method.java:497)
> 2015-10-05_14:37:34.66579 at
> org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
> 2015-10-05_14:37:34.66579 at
> org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)
> 2015-10-05_14:37:34.66580 at
> org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)
> 2015-10-05_14:37:34.66581 at
> org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:205)
> 2015-10-05_14:37:34.66581 at
> org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)
> 2015-10-05_14:37:34.66582 at
> org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)
> 2015-10-05_14:37:34.66582 at
> org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)
> 2015-10-05_14:37:34.66582 at
> org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)
> 2015-10-05_14:37:34.66583 at
> org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:308)
> 2015-10-05_14:37:34.66583 at
> org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
> 2015-10-05_14:37:34.66583 at
> org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
> 2015-10-05_14:37:34.66584 at
> org.glassfish.jersey.internal.Errors.process(Errors.java:315)
> 2015-10-05_14:37:34.66585 at
> org.glassfish.jersey.internal.Errors.process(Errors.java:297)
> 2015-10-05_14:37:34.66585 at
> org.glassfish.jersey.internal.Errors.process(Errors.java:267)
> 2015-10-05_14:37:34.66586 at
> org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
> 2015-10-05_14:37:34.66586 at
> org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:291)
> 2015-10-05_14:37:34.66586 at
> org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1140)
> 2015-10-05_14:37:34.66587 at
> org.graylog2.jersey.container.netty.NettyContainer.messageReceived(NettyContainer.java:356)
> 2015-10-05_14:37:34.66587 at
> org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
> 2015-10-05_14:37:34.66589 at
> org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
> 2015-10-05_14:37:34.66589 at
> org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
> 2015-10-05_14:37:34.66591 at
> org.jboss.netty.handler.execution.ChannelUpstreamEventRunnable.doRun(ChannelUpstreamEventRunnable.java:43)
> 2015-10-05_14:37:34.66591 at
> org.jboss.netty.handler.execution.ChannelEventRunnable.run(ChannelEventRunnable.java:67)
> 2015-10-05_14:37:34.66593 at
> com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
> 2015-10-05_14:37:34.66595 at
> org.jboss.netty.handler.execution.MemoryAwareThreadPoolExecutor$MemoryAwareRunnable.run(MemoryAwareThreadPoolExecutor.java:606)
> 2015-10-05_14:37:34.66595 at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> 2015-10-05_14:37:34.66595 at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> 2015-10-05_14:37:34.66596 at java.lang.Thread.run(Thread.java:745)
> 2015-10-05_14:37:34.66596 Caused by:
> org.elasticsearch.ElasticsearchTimeoutException: Timeout waiting for task.
> 2015-10-05_14:37:34.66597 at
> org.elasticsearch.action.support.AdapterActionFuture.actionGet(AdapterActionFuture.java:73)
> 2015-10-05_14:37:34.66597 at
> org.graylog2.indexer.elasticsearch.GlobalTimeoutClient$GlobalTimeoutActionFuture.actionGet(GlobalTimeoutClient.java:150)
> 2015-10-05_14:37:34.66597 at
> org.graylog2.indexer.searches.Searches.terms(Searches.java:283)
> 2015-10-05_14:37:34.66598 at
> org.graylog2.indexer.searches.Searches.terms(Searches.java:298)
> 2015-10-05_14:37:34.66598 at
> org.graylog2.rest.resources.sources.SourcesResource$1.call(SourcesResource.java:93)
> 2015-10-05_14:37:34.66598 at
> org.graylog2.rest.resources.sources.SourcesResource$1.call(SourcesResource.java:89)
> 2015-10-05_14:37:34.66599 at
> com.google.common.cache.LocalCache$LocalManualCache$1.load(LocalCache.java:4742)
> 2015-10-05_14:37:34.66600 at
> com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3527)
> 2015-10-05_14:37:34.66600 at
> com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2319)
> 2015-10-05_14:37:34.66600 at
> com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2282)
> 2015-10-05_14:37:34.66601 at
> com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2197)
> 2015-10-05_14:37:34.66601 ... 35 more
> 2015-10-05_14:37:47.23951 INFO [EsIndexRangeService] Calculated range of
> [graylog_4293] in [59453ms].
> 2015-10-05_14:37:47.24239 INFO [CreateNewSingleIndexRangeJob] Created
> ranges for index graylog_4293.
> 2015-10-05_14:37:47.24246 INFO [SystemJobManager] SystemJob
> <82175554-6b6e-11e5-b272-0ae24e7f4757>
> [org.graylog2.indexer.ranges.CreateNewSingleIndexRangeJob] finished in
> 59456ms.
> 2015-10-05_14:37:47.45459 INFO [EsIndexRangeService] Calculated range of
> [graylog_4292] in [59672ms].
>
>
>
> On Monday, October 5, 2015 at 8:17:45 AM UTC-6, Jochen Schalanda wrote:
>>
>> Hi Jesse,
>>
>> did you manually trigger the calculation of all the index ranges?
>>
>> During normal operations of Graylog 1.2.x, only the index range of the
>> latest index should be calculated and stored (in contrast to Graylog 1.1.x
>> and earlier, which most of the time calculated all index ranges).
>>
>> Cheers,
>> Jochen
>>
>> On Saturday, 3 October 2015 19:11:15 UTC+2, Jesse Skrivseth wrote:
>>>
>>> A few examples of index recalc performance differences:
>>>
>>> In 1.1.6
>>> ...
>>> 2015-09-04_03:56:38.19431 INFO [RebuildIndexRangesJob] Calculated range
>>> of [graylog_2075] in [9ms].
>>> 2015-09-04_03:56:38.20487 INFO [RebuildIndexRangesJob] Calculated range
>>> of [graylog_1800] in [10ms].
>>> 2015-09-04_03:56:38.21176 INFO [RebuildIndexRangesJob] Calculated range
>>> of [graylog_1802] in [6ms].
>>> 2015-09-04_03:56:38.22028 INFO [RebuildIndexRangesJob] Calculated range
>>> of [graylog_1801] in [8ms].
>>> 2015-09-04_03:56:38.23003 INFO [RebuildIndexRangesJob] Calculated range
>>> of [graylog_1808] in [9ms].
>>> 2015-09-04_03:56:38.23855 INFO [RebuildIndexRangesJob] Calculated range
>>> of [graylog_1807] in [8ms].
>>> 2015-09-04_03:56:38.24877 INFO [RebuildIndexRangesJob] Calculated range
>>> of [graylog_1809] in [10ms].
>>> 2015-09-04_03:56:38.26011 INFO [RebuildIndexRangesJob] Calculated range
>>> of [graylog_1804] in [11ms].
>>> 2015-09-04_03:56:38.26902 INFO [RebuildIndexRangesJob] Calculated range
>>> of [graylog_1803] in [8ms].
>>> 2015-09-04_03:56:38.28049 INFO [RebuildIndexRangesJob] Calculated range
>>> of [graylog_1806] in [11ms].
>>> 2015-09-04_03:56:38.29289 INFO [RebuildIndexRangesJob] Calculated range
>>> of [graylog_1805] in [12ms].
>>> 2015-09-04_03:56:38.41557 INFO [RebuildIndexRangesJob] Done calculating
>>> index ranges for 800 indices. Took 10608ms.
>>>
>>> In 1.2.1:
>>> ...
>>> 2015-10-03_17:00:59.70210 INFO [EsIndexRangeService] Calculated range
>>> of [graylog_3358] in [1609ms].
>>> 2015-10-03_17:01:05.63202 INFO [EsIndexRangeService] Calculated range
>>> of [graylog_3357] in [50ms].
>>> 2015-10-03_17:01:08.85062 INFO [EsIndexRangeService] Calculated range
>>> of [graylog_3359] in [47ms].
>>> 2015-10-03_17:01:12.39922 INFO [EsIndexRangeService] Calculated range
>>> of [graylog_3365] in [119ms].
>>> 2015-10-03_17:01:15.80573 INFO [EsIndexRangeService] Calculated range
>>> of [graylog_3364] in [40ms].
>>> 2015-10-03_17:01:19.29222 INFO [EsIndexRangeService] Calculated range
>>> of [graylog_3367] in [43ms].
>>> 2015-10-03_17:01:22.98674 INFO [EsIndexRangeService] Calculated range
>>> of [graylog_3366] in [142ms].
>>> 2015-10-03_17:01:29.74936 INFO [EsIndexRangeService] Calculated range
>>> of [graylog_3361] in [120ms].
>>> 2015-10-03_17:01:34.11754 INFO [EsIndexRangeService] Calculated range
>>> of [graylog_3360] in [128ms].
>>> 2015-10-03_17:01:37.91544 INFO [EsIndexRangeService] Calculated range
>>> of [graylog_3363] in [134ms].
>>> 2015-10-03_17:01:41.41116 INFO [EsIndexRangeService] Calculated range
>>> of [graylog_3362] in [237ms].
>>> 2015-10-03_17:01:45.31576 INFO [RebuildIndexRangesJob] Done calculating
>>> index ranges for 1855 indices. Took 9551409ms.
>>>
>>> For good measure, I tried scaling the ES cluster up and down.
>>> Performance is exactly the same whether I run on a single large server vs 4
>>> smaller servers.
>>>
>>> On Friday, October 2, 2015 at 9:29:37 AM UTC-6, Jesse Skrivseth wrote:
>>>>
>>>> Note that for the 1800 indices we have in this instance, the ~5 second
>>>> delay between each index during range calculation adds up to ~150 minutes
>>>> of additional delay when calculating ranges. My "> 20 minutes" comment
>>>> should be more like "> 2.5 hours", plus actual time spent calculating
>>>> ranges.
>>>>
>>>
--
You received this message because you are subscribed to the Google Groups
"Graylog Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To view this discussion on the web visit
https://groups.google.com/d/msgid/graylog2/a33a1567-721a-43eb-af47-01aebdc13f1c%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
