Hi Jochen, Thanks for your efforts on this. Subscribed.
On Tuesday, October 6, 2015 at 6:03:23 AM UTC-6, Jochen Schalanda wrote: > > 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/e41c4652-c8a6-487d-94c5-f444cf77b219%40googlegroups.com. For more options, visit https://groups.google.com/d/optout.
