You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by "Michael Braun (JIRA)" <ji...@apache.org> on 2016/08/29 15:30:21 UTC
[jira] [Created] (SOLR-9453) NullPointerException on PeerSync
recovery
Michael Braun created SOLR-9453:
-----------------------------------
Summary: NullPointerException on PeerSync recovery
Key: SOLR-9453
URL: https://issues.apache.org/jira/browse/SOLR-9453
Project: Solr
Issue Type: Bug
Security Level: Public (Default Security Level. Issues are Public)
Affects Versions: 6.2
Reporter: Michael Braun
Just updated to 6.2.0 (previously using 6.1.0) and we restarted the cluster a few times - for one replica trying to sync on a shard, we got this on a bootup and it's seemingly stuck. Cluster has 96 shards, 2 replicas per shard.
{code}
java.lang.NullPointerException
at org.apache.solr.update.PeerSync.handleUpdates(PeerSync.java:605)
at org.apache.solr.update.PeerSync.handleResponse(PeerSync.java:344)
at org.apache.solr.update.PeerSync.sync(PeerSync.java:257)
at org.apache.solr.handler.component.RealTimeGetComponent.processSync(RealTimeGetComponent.java:658)
at org.apache.solr.handler.component.RealTimeGetComponent.processGetVersions(RealTimeGetComponent.java:623)
at org.apache.solr.handler.component.RealTimeGetComponent.process(RealTimeGetComponent.java:117)
at org.apache.solr.handler.component.SearchHandler.handleRequestBody(SearchHandler.java:295)
at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:154)
at org.apache.solr.core.SolrCore.execute(SolrCore.java:2089)
at org.apache.solr.servlet.HttpSolrCall.execute(HttpSolrCall.java:652)
at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:459)
at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:257)
at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:208)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:581)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1160)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1092)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:213)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:119)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
at org.eclipse.jetty.server.Server.handle(Server.java:518)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:308)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:244)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:246)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:156)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572)
at java.lang.Thread.run(Thread.java:745)
{code}
Before it in the log , pasting some relevant lines with full IPs redacted:
{code}ERROR - 2016-08-29 15:10:28.940; org.apache.solr.common.SolrException; Error while trying to recover. core=ourcollection_shard51_replica2:org.apache.solr.common.SolrException: No registered leader was found after waiting for 4000ms , collection: ourcollection slice: shard51
at org.apache.solr.common.cloud.ZkStateReader.getLeaderRetry(ZkStateReader.java:746)
at org.apache.solr.common.cloud.ZkStateReader.getLeaderRetry(ZkStateReader.java:732)
at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:305)
at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:221)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
globalRequestId:
INFO - 2016-08-29 15:10:28.940; org.apache.solr.cloud.RecoveryStrategy; Replay not started, or was not successful... still buffering updates. globalRequestId:
ERROR - 2016-08-29 15:10:28.940; org.apache.solr.cloud.RecoveryStrategy; Recovery failed - trying again... (0) globalRequestId:
...
INFO - 2016-08-29 15:10:29.009; org.apache.solr.servlet.HttpSolrCall; [admin] webapp=null path=/admin/cores params={nodeName=x.x.x.222:8983_solr&onlyIfLeaderActive=true&core=ourcollection_shard27_replica2&coreNodeName=core_node33&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=0 QTime=1002 globalRequestId:
INFO - 2016-08-29 15:10:29.009; org.apache.solr.handler.admin.CoreAdminOperation; In WaitForState(recovering): collection=ourcollection, shard=shard39, thisCore=ourcollection_shard39_replica2, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=recovering, localState=active, nodeName=x.x.x.222:8983_solr, coreNodeName=core_node59, onlyIfActiveCheckResult=false, nodeProps: core_node59:{"core":"ourcollection_shard39_replica1","base_url":"http://x.x.x.222:8983/solr","node_name":"x.x.x.222:8983_solr","state":"recovering"} globalRequestId:
INFO - 2016-08-29 15:10:29.010; org.apache.solr.handler.admin.CoreAdminOperation; Waited coreNodeName: core_node59, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds. globalRequestId:
INFO - 2016-08-29 15:10:29.010; org.apache.solr.servlet.HttpSolrCall; [admin] webapp=null path=/admin/cores params={nodeName=x.x.x.222:8983_solr&onlyIfLeaderActive=true&core=ourcollection_shard39_replica2&coreNodeName=core_node59&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=0 QTime=1002 globalRequestId:
INFO - 2016-08-29 15:10:29.170; org.apache.solr.update.PeerSync; PeerSync: core=ourcollection_shard51_replica2 url=http://x.x.x.162:8983/solr Received 98 versions from http://x.x.x.222:8983/solr/ourcollection_shard51_replica1/ fingerprint:{maxVersionSpecified=9223372036854775807, maxVersionEncountered=1544008888205967360, maxInHash=1544008888205967360, versionsHash=3277155204018391078, numVersions=3589651, numDocs=3589651, maxDoc=3847400} globalRequestId:
INFO - 2016-08-29 15:10:29.175; org.apache.solr.update.PeerSync; PeerSync: core=ourcollection_shard51_replica2 url=http://x.x.x.162:8983/solr Requesting updates from http://x.x.x.222:8983/solr/ourcollection_shard51_replica1/n=50 versions=-1544008879780659200...-1544008879780659200,-1544008902308265984...-1544008902308265984,-1544008902828359680...-1544008902828359680,-1544008902881837056...-1544008902881837056,-1544008902939508736...-1544008902939508736,-1544008903530905600...-1544008903530905600,-1544008903635763200...-1544008903635763200,-1544008903795146752...-1544008903795146752,-1544008903846526976...-1544008903846526976,-1544008903912587264...-1544008903912587264,-1544008903972356096...-1544008903972356096,-1544008904108670976...-1544008904108670976,-1544008904164245504...-1544008904164245504,-1544008904237645824...-1544008904237645824,-1544008904401223680...-1544008904401223680,-1544008904467283968...-1544008904467283968,-1544008904776613888...-1544008904776613888 globalRequestId:
ERROR - 2016-08-29 15:10:29.181; org.apache.solr.common.SolrException; java.lang.NullPointerException
at org.apache.solr.update.PeerSync.handleUpdates(PeerSync.java:605)
at org.apache.solr.update.PeerSync.handleResponse(PeerSync.java:344)
at org.apache.solr.update.PeerSync.sync(PeerSync.java:257)
at org.apache.solr.handler.component.RealTimeGetComponent.processSync(RealTimeGetComponent.java:658)
at org.apache.solr.handler.component.RealTimeGetComponent.processGetVersions(RealTimeGetComponent.java:623)
at org.apache.solr.handler.component.RealTimeGetComponent.process(RealTimeGetComponent.java:117)
at org.apache.solr.handler.component.SearchHandler.handleRequestBody(SearchHandler.java:295)
at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:154)
at org.apache.solr.core.SolrCore.execute(SolrCore.java:2089)
at org.apache.solr.servlet.HttpSolrCall.execute(HttpSolrCall.java:652)
at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:459)
at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:257)
at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:208)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:581)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1160)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1092)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:213)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:119)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
at org.eclipse.jetty.server.Server.handle(Server.java:518)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:308)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:244)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:246)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:156)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572)
at java.lang.Thread.run(Thread.java:745)
globalRequestId:
INFO - 2016-08-29 15:10:29.182; org.apache.solr.core.SolrCore; [ourcollection_shard51_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&getVersions=100&sync=http://x.x.x.222:8983/solr/ourcollection_shard51_replica1/&wt=javabin&version=2} status=500 QTime=422 globalRequestId:
ERROR - 2016-08-29 15:10:29.182; org.apache.solr.common.SolrException; null:java.lang.NullPointerException
at org.apache.solr.update.PeerSync.handleUpdates(PeerSync.java:605)
at org.apache.solr.update.PeerSync.handleResponse(PeerSync.java:344)
at org.apache.solr.update.PeerSync.sync(PeerSync.java:257)
at org.apache.solr.handler.component.RealTimeGetComponent.processSync(RealTimeGetComponent.java:658)
at org.apache.solr.handler.component.RealTimeGetComponent.processGetVersions(RealTimeGetComponent.java:623)
at org.apache.solr.handler.component.RealTimeGetComponent.process(RealTimeGetComponent.java:117)
at org.apache.solr.handler.component.SearchHandler.handleRequestBody(SearchHandler.java:295)
at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:154)
at org.apache.solr.core.SolrCore.execute(SolrCore.java:2089)
at org.apache.solr.servlet.HttpSolrCall.execute(HttpSolrCall.java:652)
at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:459)
at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:257)
at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:208)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:581)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1160)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1092)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:213)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:119)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
at org.eclipse.jetty.server.Server.handle(Server.java:518)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:308)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:244)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:246)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:156)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572)
at java.lang.Thread.run(Thread.java:745)
globalRequestId:
INFO - 2016-08-29 15:10:29.219; org.apache.solr.handler.admin.CoreAdminOperation; It has been requested that we recover: core=ourcollection_shard51_replica2 globalRequestId:
INFO - 2016-08-29 15:10:29.220; org.apache.solr.servlet.HttpSolrCall; [admin] webapp=null path=/admin/cores params={core=ourcollection_shard51_replica2&action=REQUESTRECOVERY&wt=javabin&version=2} status=0 QTime=1 globalRequestId:
INFO - 2016-08-29 15:10:29.684; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:29.686; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6254] to [6255] globalRequestId:
INFO - 2016-08-29 15:10:29.929; org.apache.solr.cloud.ZkController; We are http://x.x.x.162:8983/solr/ourcollection_shard51_replica2/ and leader is http://x.x.x.222:8983/solr/ourcollection_shard51_replica1/ globalRequestId:
INFO - 2016-08-29 15:10:29.929; org.apache.solr.cloud.ZkController; No LogReplay needed for core=ourcollection_shard51_replica2 baseURL=http://x.x.x.162:8983/solr globalRequestId:
INFO - 2016-08-29 15:10:29.930; org.apache.solr.cloud.ZkController; Core needs to recover:ourcollection_shard51_replica2 globalRequestId:
INFO - 2016-08-29 15:10:29.930; org.apache.solr.common.cloud.ZkStateReader; Forcing refresh of watched collection state for ourcollection globalRequestId:
INFO - 2016-08-29 15:10:30.080; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:30.081; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6255] to [6256] globalRequestId:
INFO - 2016-08-29 15:10:30.544; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:30.545; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6256] to [6257] globalRequestId:
INFO - 2016-08-29 15:10:31.764; org.apache.solr.core.SolrCore; [ourcollection_shard3_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=1 globalRequestId:
INFO - 2016-08-29 15:10:32.172; org.apache.solr.core.SolrCore; [ourcollection_shard15_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:32.272; org.apache.solr.core.SolrCore; [ourcollection_shard27_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:32.384; org.apache.solr.core.SolrCore; [ourcollection_shard39_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:32.483; org.apache.solr.core.SolrCore; [ourcollection_shard51_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:32.585; org.apache.solr.core.SolrCore; [ourcollection_shard63_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:32.690; org.apache.solr.core.SolrCore; [ourcollection_shard75_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:32.780; org.apache.solr.core.SolrCore; [ourcollection_shard87_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:33.614; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:33.615; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6257] to [6258] globalRequestId:
INFO - 2016-08-29 15:10:33.754; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:33.756; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6258] to [6259] globalRequestId:
INFO - 2016-08-29 15:10:34.633; org.apache.solr.core.SolrCore; [ourcollection_shard3_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:34.732; org.apache.solr.core.SolrCore; [ourcollection_shard15_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:34.820; org.apache.solr.core.SolrCore; [ourcollection_shard27_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:34.912; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:34.914; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6259] to [6260] globalRequestId:
INFO - 2016-08-29 15:10:34.917; org.apache.solr.core.SolrCore; [ourcollection_shard39_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:34.936; org.apache.solr.core.SolrCore; [ourcollection_shard3_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=true&getVersions=100&wt=javabin&version=2} status=0 QTime=1 globalRequestId:
INFO - 2016-08-29 15:10:34.936; org.apache.solr.core.SolrCore; [ourcollection_shard15_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=true&getVersions=100&wt=javabin&version=2} status=0 QTime=1 globalRequestId:
INFO - 2016-08-29 15:10:34.937; org.apache.solr.core.SolrCore; [ourcollection_shard63_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=true&getVersions=100&wt=javabin&version=2} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:34.938; org.apache.solr.core.SolrCore; [ourcollection_shard87_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=true&getVersions=100&wt=javabin&version=2} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:34.940; org.apache.solr.core.SolrCore; [ourcollection_shard75_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=true&getVersions=100&wt=javabin&version=2} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:34.940; org.apache.solr.core.SolrCore; [ourcollection_shard15_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&checkCanHandleVersionRanges=false&wt=javabin&version=2} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:34.940; org.apache.solr.core.SolrCore; [ourcollection_shard3_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&checkCanHandleVersionRanges=false&wt=javabin&version=2} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:34.941; org.apache.solr.core.SolrCore; [ourcollection_shard63_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&checkCanHandleVersionRanges=false&wt=javabin&version=2} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:34.942; org.apache.solr.core.SolrCore; [ourcollection_shard87_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&checkCanHandleVersionRanges=false&wt=javabin&version=2} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:34.944; org.apache.solr.core.SolrCore; [ourcollection_shard75_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&checkCanHandleVersionRanges=false&wt=javabin&version=2} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:35.002; org.apache.solr.core.SolrCore; [ourcollection_shard51_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:35.087; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:35.088; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6260] to [6261] globalRequestId:
INFO - 2016-08-29 15:10:35.119; org.apache.solr.core.SolrCore; [ourcollection_shard63_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:35.210; org.apache.solr.core.SolrCore; [ourcollection_shard75_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:35.291; org.apache.solr.core.SolrCore; [ourcollection_shard87_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:35.312; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:35.314; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6261] to [6262] globalRequestId:
INFO - 2016-08-29 15:10:35.606; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:35.607; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6262] to [6263] globalRequestId:
INFO - 2016-08-29 15:10:36.015; org.apache.solr.core.SolrCore; [ourcollection_shard39_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=true&getVersions=100&wt=javabin&version=2} status=0 QTime=1 globalRequestId:
INFO - 2016-08-29 15:10:36.015; org.apache.solr.core.SolrCore; [ourcollection_shard27_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=true&getVersions=100&wt=javabin&version=2} status=0 QTime=1 globalRequestId:
INFO - 2016-08-29 15:10:36.019; org.apache.solr.core.SolrCore; [ourcollection_shard27_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&checkCanHandleVersionRanges=false&wt=javabin&version=2} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:36.019; org.apache.solr.core.SolrCore; [ourcollection_shard39_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&checkCanHandleVersionRanges=false&wt=javabin&version=2} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:36.071; org.apache.solr.core.SolrCore; [ourcollection_shard27_replica2] webapp=/solr path=/get params={getUpdates=1544008888623300608...1544008888760664064,1544008889002885120...1544008889297534976,1544008889423364096...1544008889423364096,1544008889510395904...1544008889514590208,1544008889779879936...1544008889900466176,1544008890222379008...1544008890222379008,1544008890367082496...1544008890367082496,1544008890523320320...1544008890572603392&distrib=false&qt=/get&onlyIfActive=false&wt=javabin&version=2} status=0 QTime=47 globalRequestId:
INFO - 2016-08-29 15:10:36.282; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:36.283; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6263] to [6264] globalRequestId:
INFO - 2016-08-29 15:10:36.774; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:36.775; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6264] to [6265] globalRequestId:
INFO - 2016-08-29 15:10:36.984; org.apache.solr.core.SolrCore; [ourcollection_shard3_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:37.039; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:37.040; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6265] to [6266] globalRequestId:
INFO - 2016-08-29 15:10:37.079; org.apache.solr.core.SolrCore; [ourcollection_shard15_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:37.170; org.apache.solr.core.SolrCore; [ourcollection_shard27_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:37.299; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:37.301; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6266] to [6267] globalRequestId:
INFO - 2016-08-29 15:10:37.326; org.apache.solr.core.SolrCore; [ourcollection_shard39_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:37.458; org.apache.solr.core.SolrCore; [ourcollection_shard51_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:37.546; org.apache.solr.core.SolrCore; [ourcollection_shard63_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:37.641; org.apache.solr.core.SolrCore; [ourcollection_shard75_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:37.771; org.apache.solr.core.SolrCore; [ourcollection_shard87_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:37.983; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:37.984; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6267] to [6268] globalRequestId:
INFO - 2016-08-29 15:10:38.711; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:38.712; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6268] to [6269] globalRequestId:
INFO - 2016-08-29 15:10:38.891; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:38.892; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6269] to [6270] globalRequestId:
INFO - 2016-08-29 15:10:38.941; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=[ourcollection_shard51_replica2] globalRequestId:
INFO - 2016-08-29 15:10:38.941; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null} globalRequestId:
INFO - 2016-08-29 15:10:38.941; org.apache.solr.cloud.RecoveryStrategy; Publishing state of core [ourcollection_shard51_replica2] as recovering, leader is [http://x.x.x.222:8983/solr/ourcollection_shard51_replica1/] and I am [http://x.x.x.162:8983/solr/ourcollection_shard51_replica2/] globalRequestId:
INFO - 2016-08-29 15:10:38.941; org.apache.solr.cloud.ZkController; publishing state=recovering globalRequestId:
INFO - 2016-08-29 15:10:38.941; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property globalRequestId:
INFO - 2016-08-29 15:10:38.949; org.apache.solr.cloud.RecoveryStrategy; Sending prep recovery command to [http://x.x.x.222:8983/solr]; [WaitForState: action=PREPRECOVERY&core=ourcollection_shard51_replica1&nodeName=x.x.x.162:8983_solr&coreNodeName=core_node147&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true] globalRequestId:
INFO - 2016-08-29 15:10:39.058; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:39.060; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6270] to [6271] globalRequestId:
INFO - 2016-08-29 15:10:39.508; org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/ourcollection/state.json] for collection [ourcollection] has occurred - updating... (live nodes size: [24]) globalRequestId:
INFO - 2016-08-29 15:10:39.509; org.apache.solr.common.cloud.ZkStateReader; Updating data for [ourcollection] from [6271] to [6272] globalRequestId:
INFO - 2016-08-29 15:10:41.681; org.apache.solr.core.SolrCore; [ourcollection_shard3_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:41.781; org.apache.solr.core.SolrCore; [ourcollection_shard15_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:41.864; org.apache.solr.core.SolrCore; [ourcollection_shard27_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:41.958; org.apache.solr.core.SolrCore; [ourcollection_shard39_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:42.039; org.apache.solr.core.SolrCore; [ourcollection_shard51_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:42.124; org.apache.solr.core.SolrCore; [ourcollection_shard63_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:42.214; org.apache.solr.core.SolrCore; [ourcollection_shard75_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:42.294; org.apache.solr.core.SolrCore; [ourcollection_shard87_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:43.878; org.apache.solr.core.SolrCore; [ourcollection_shard3_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:43.966; org.apache.solr.core.SolrCore; [ourcollection_shard15_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:44.046; org.apache.solr.core.SolrCore; [ourcollection_shard27_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:44.137; org.apache.solr.core.SolrCore; [ourcollection_shard39_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:44.219; org.apache.solr.core.SolrCore; [ourcollection_shard51_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:44.304; org.apache.solr.core.SolrCore; [ourcollection_shard63_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:44.395; org.apache.solr.core.SolrCore; [ourcollection_shard75_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:44.473; org.apache.solr.core.SolrCore; [ourcollection_shard87_replica2] webapp=/solr path=/admin/luke params={show=index&numTerms=0&wt=json} status=0 QTime=0 globalRequestId:
INFO - 2016-08-29 15:10:46.963; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from [http://x.x.x.222:8983/solr/ourcollection_shard51_replica1/] - recoveringAfterStartup=[true] globalRequestId:
INFO - 2016-08-29 15:10:46.963; org.apache.solr.update.PeerSync; PeerSync: core=ourcollection_shard51_replica2 url=http://x.x.x.162:8983/solr START replicas=[http://x.x.x.222:8983/solr/ourcollection_shard51_replica1/] nUpdates=100 globalRequestId:
INFO - 2016-08-29 15:10:46.969; org.apache.solr.update.PeerSync; PeerSync: core=ourcollection_shard51_replica2 url=http://x.x.x.162:8983/solr Received 98 versions from http://x.x.x.222:8983/solr/ourcollection_shard51_replica1/ fingerprint:{maxVersionSpecified=9223372036854775807, maxVersionEncountered=1544008888205967360, maxInHash=1544008888205967360, versionsHash=3277155204018391078, numVersions=3589651, numDocs=3589651, maxDoc=3847400} globalRequestId:
INFO - 2016-08-29 15:10:46.973; org.apache.solr.update.PeerSync; PeerSync: core=ourcollection_shard51_replica2 url=http://x.x.x.162:8983/solr Requesting updates from http://x.x.x.222:8983/solr/ourcollection_shard51_replica1/n=50 versions=-1544008879780659200...-1544008879780659200,-1544008902308265984...-1544008902308265984,-1544008902828359680...-1544008902828359680,-1544008902881837056...-1544008902881837056,-1544008902939508736...-1544008902939508736,-1544008903530905600...-1544008903530905600,-1544008903635763200...-1544008903635763200,-1544008903795146752...-1544008903795146752,-1544008903846526976...-1544008903846526976,-1544008903912587264...-1544008903912587264,-1544008903972356096...-1544008903972356096,-1544008904108670976...-1544008904108670976,-1544008904164245504...-1544008904164245504,-1544008904237645824...-1544008904237645824,-1544008904401223680...-1544008904401223680,-1544008904467283968...-1544008904467283968,-1544008904776613888...-1544008904776613888 globalRequestId:
ERROR - 2016-08-29 15:10:46.979; org.apache.solr.common.SolrException; Error while trying to recover. core=ourcollection_shard51_replica2:java.lang.NullPointerException
at org.apache.solr.update.PeerSync.handleUpdates(PeerSync.java:605)
at org.apache.solr.update.PeerSync.handleResponse(PeerSync.java:344)
at org.apache.solr.update.PeerSync.sync(PeerSync.java:257)
at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:376)
at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:221)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
globalRequestId:
INFO - 2016-08-29 15:10:46.979; org.apache.solr.cloud.RecoveryStrategy; Replay not started, or was not successful... still buffering updates. globalRequestId:
ERROR - 2016-08-29 15:10:46.979; org.apache.solr.cloud.RecoveryStrategy; Recovery failed - trying again... (1) globalRequestId:
INFO - 2016-08-29 15:10:46.979; org.apache.solr.cloud.RecoveryStrategy; Wait [4.0] seconds before trying to recover again (attempt=2) globalRequestId:
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org