You are viewing a plain text version of this content. The canonical link for it is here.
Posted to solr-user@lucene.apache.org by Susheel Kumar <su...@gmail.com> on 2018/09/22 06:20:19 UTC
POSSIBLE RESOURCE LEAK- solr 6.6.2
Hello,
I noticed one of the replica's in Recover Failed status and after trying to
recreate the replica/restart the node to recover, I see below error from
solr log. The leader for this shard8 replica2 i.e. replica1@server 61
seems to be fine and serving the queries.
What does this indicate "SolrIndexWriter was not closed prior to
finalize(), indicates a bug -- POSSIBLE RESOURCE LEAK!!!" from below log.
2018-09-22 06:00:13.686 ERROR (Finalizer) [ ]
o.a.s.u.SolrIndexWriter Error closing IndexWriter2018-09-22
05:58:13.409 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16
x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=5
2018-09-22 05:58:13.686 INFO (qtp834133664-19) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=39
2018-09-22 05:58:19.338 ERROR
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.ReplicationHandler Index
fetch failed :org.apache.solr.common.SolrException: Index fetch failed
:
at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:598)
at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:301)
at org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:400)
at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:219)
at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:471)
at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:284)
at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
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:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.lucene.index.CorruptIndexException: codec header
mismatch: actual header=1997958933 vs expected header=1071082519
(resource=BufferedChecksumIndexInput(MMapIndexInput(path="/app/solr/data/COLL_shard8_replica2/data/index/_8ktm.fnm")))
at org.apache.lucene.codecs.CodecUtil.checkHeader(CodecUtil.java:196)
at org.apache.lucene.codecs.CodecUtil.checkIndexHeader(CodecUtil.java:255)
at org.apache.lucene.codecs.lucene60.Lucene60FieldInfosFormat.read(Lucene60FieldInfosFormat.java:117)
at org.apache.lucene.index.IndexWriter.readFieldInfos(IndexWriter.java:1063)
at org.apache.lucene.index.IndexWriter.getFieldNumberMap(IndexWriter.java:1075)
at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:960)
at org.apache.solr.update.SolrIndexWriter.<init>(SolrIndexWriter.java:118)
at org.apache.solr.update.SolrIndexWriter.create(SolrIndexWriter.java:93)
at org.apache.solr.update.DefaultSolrCoreState.createMainIndexWriter(DefaultSolrCoreState.java:257)
at org.apache.solr.update.DefaultSolrCoreState.changeWriter(DefaultSolrCoreState.java:220)
at org.apache.solr.update.DefaultSolrCoreState.openIndexWriter(DefaultSolrCoreState.java:245)
at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:551)
... 12 more
Suppressed: org.apache.lucene.index.CorruptIndexException:
checksum failed (hardware problem?) : expected=e42fdf3e
actual=c0432e62
(resource=BufferedChecksumIndexInput(MMapIndexInput(path="/app/solr/data/COLL_shard8_replica2/data/index/_8ktm.fnm")))
at
org.apache.lucene.codecs.CodecUtil.checkFooter(CodecUtil.java:419)
at
org.apache.lucene.codecs.CodecUtil.checkFooter(CodecUtil.java:462)
at
org.apache.lucene.codecs.lucene60.Lucene60FieldInfosFormat.read(Lucene60FieldInfosFormat.java:171)
... 21 more
2018-09-22 05:58:19.338 ERROR
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Error
while trying to recover:org.apache.solr.common.SolrException:
Replication for recovery failed.
at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:222)
at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:471)
at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:284)
at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
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:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2018-09-22 05:58:19.338 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Replay
not started, or was not successful... still buffering updates.
2018-09-22 05:58:19.338 ERROR
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy
Recovery failed - trying again... (0)
2018-09-22 05:58:19.338 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Wait
[2.0] seconds before trying to recover again (attempt=1)
2018-09-22 05:58:23.352 INFO (qtp834133664-20) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=0
2018-09-22 05:58:23.486 INFO (qtp834133664-21) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=18
2018-09-22 05:58:23.763 INFO (qtp834133664-22) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=53
2018-09-22 05:58:29.339 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Begin
buffering updates. core=[COLL_shard8_replica2]
2018-09-22 05:58:29.339 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.u.UpdateLog Restarting
buffering. previous=RecoveryInfo{adds=0 deletes=0 deleteByQuery=0
errors=0 positionOfStart=0}
2018-09-22 05:58:29.339 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.u.UpdateLog Starting to
buffer updates. FSUpdateLog{state=BUFFERING,
tlog=tlog{file=/app/solr/data/COLL_shard8_replica2/data/tlog/tlog.0000000000000000000.1612285920588857344
refcount=2}}
2018-09-22 05:58:29.339 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy
Publishing state of core [COLL_shard8_replica2] as recovering, leader
is [http://server61:8080/solr/COLL_shard8_replica1/] and I am
[http://server62:8080/solr/COLL_shard8_replica2/]
2018-09-22 05:58:29.343 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Sending
prep recovery command to [http://server61:8080/solr]; [WaitForState:
action=PREPRECOVERY&core=COLL_shard8_replica1&nodeName=server62:8080_solr&coreNodeName=core_node16&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
2018-09-22 05:58:29.351 INFO
(zkCallback-5-thread-23-processing-n:server62:8080_solr) [ ]
o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
state:SyncConnected type:NodeDataChanged
path:/collections/COLL/state.json] for collection [COLL] has occurred
- updating... (live nodes size: [16])
2018-09-22 05:58:31.846 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy
Starting Replication Recovery.
2018-09-22 05:58:31.846 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy
Attempting to replicate from
[http://server61:8080/solr/COLL_shard8_replica1/].
2018-09-22 05:58:32.234 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Master's
generation: 51970
2018-09-22 05:58:32.234 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Master's
version: 1537595911854
2018-09-22 05:58:32.234 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Slave's
generation: 1
2018-09-22 05:58:32.234 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Slave's
version: 0
2018-09-22 05:58:32.234 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Starting
replication process
2018-09-22 05:58:32.290 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Number of
files in latest index in master: 257
2018-09-22 05:58:32.309 ERROR
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.ReplicationHandler Index
fetch failed :org.apache.solr.common.SolrException: Index fetch failed
:
at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:598)
at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:301)
at org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:400)
at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:219)
at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:471)
at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:284)
at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
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:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.lucene.index.CorruptIndexException: codec header
mismatch: actual header=1997958933 vs expected header=1071082519
(resource=BufferedChecksumIndexInput(MMapIndexInput(path="/app/solr/data/COLL_shard8_replica2/data/index/_8ktm.fnm")))
at org.apache.lucene.codecs.CodecUtil.checkHeader(CodecUtil.java:196)
at org.apache.lucene.codecs.CodecUtil.checkIndexHeader(CodecUtil.java:255)
at org.apache.lucene.codecs.lucene60.Lucene60FieldInfosFormat.read(Lucene60FieldInfosFormat.java:117)
at org.apache.lucene.index.IndexWriter.readFieldInfos(IndexWriter.java:1063)
at org.apache.lucene.index.IndexWriter.getFieldNumberMap(IndexWriter.java:1075)
at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:960)
at org.apache.solr.update.SolrIndexWriter.<init>(SolrIndexWriter.java:118)
at org.apache.solr.update.SolrIndexWriter.create(SolrIndexWriter.java:93)
at org.apache.solr.update.DefaultSolrCoreState.createMainIndexWriter(DefaultSolrCoreState.java:257)
at org.apache.solr.update.DefaultSolrCoreState.changeWriter(DefaultSolrCoreState.java:220)
at org.apache.solr.update.DefaultSolrCoreState.newIndexWriter(DefaultSolrCoreState.java:229)
at org.apache.solr.update.DirectUpdateHandler2.newIndexWriter(DirectUpdateHandler2.java:726)
at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:457)
... 12 more
Suppressed: org.apache.lucene.index.CorruptIndexException:
checksum failed (hardware problem?) : expected=e42fdf3e
actual=c0432e62
(resource=BufferedChecksumIndexInput(MMapIndexInput(path="/app/solr/data/COLL_shard8_replica2/data/index/_8ktm.fnm")))
at
org.apache.lucene.codecs.CodecUtil.checkFooter(CodecUtil.java:419)
at
org.apache.lucene.codecs.CodecUtil.checkFooter(CodecUtil.java:462)
at
org.apache.lucene.codecs.lucene60.Lucene60FieldInfosFormat.read(Lucene60FieldInfosFormat.java:171)
... 22 more
2018-09-22 05:58:32.309 ERROR
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Error
while trying to recover:org.apache.solr.common.SolrException:
Replication for recovery failed.
at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:222)
at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:471)
at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:284)
at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
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:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2018-09-22 05:58:32.310 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Replay
not started, or was not successful... still buffering updates.
2018-09-22 05:58:32.310 ERROR
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy
Recovery failed - trying again... (1)
2018-09-22 05:58:32.310 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Wait
[4.0] seconds before trying to recover again (attempt=2)
2018-09-22 05:58:33.423 INFO (qtp834133664-15) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=4
2018-09-22 05:58:33.548 INFO (qtp834133664-21) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=3
2018-09-22 05:58:33.834 INFO (qtp834133664-19) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=44
2018-09-22 05:58:43.480 INFO (qtp834133664-13) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=2
2018-09-22 05:58:43.624 INFO (qtp834133664-21) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=8
2018-09-22 05:58:43.882 INFO (qtp834133664-22) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=23
2018-09-22 05:58:52.310 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Begin
buffering updates. core=[COLL_shard8_replica2]
2018-09-22 05:58:52.310 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.u.UpdateLog Restarting
buffering. previous=RecoveryInfo{adds=0 deletes=0 deleteByQuery=0
errors=0 positionOfStart=2630296}
2018-09-22 05:58:52.310 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.u.UpdateLog Starting to
buffer updates. FSUpdateLog{state=BUFFERING,
tlog=tlog{file=/app/solr/data/COLL_shard8_replica2/data/tlog/tlog.0000000000000000000.1612285920588857344
refcount=2}}
2018-09-22 05:58:52.310 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy
Publishing state of core [COLL_shard8_replica2] as recovering, leader
is [http://server61:8080/solr/COLL_shard8_replica1/] and I am
[http://server62:8080/solr/COLL_shard8_replica2/]
2018-09-22 05:58:52.317 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Sending
prep recovery command to [http://server61:8080/solr]; [WaitForState:
action=PREPRECOVERY&core=COLL_shard8_replica1&nodeName=server62:8080_solr&coreNodeName=core_node16&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
2018-09-22 05:58:52.325 INFO
(zkCallback-5-thread-23-processing-n:server62:8080_solr) [ ]
o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
state:SyncConnected type:NodeDataChanged
path:/collections/COLL/state.json] for collection [COLL] has occurred
- updating... (live nodes size: [16])
2018-09-22 05:58:53.538 INFO (qtp834133664-20) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=8
2018-09-22 05:58:53.679 INFO (qtp834133664-21) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=4
2018-09-22 05:58:53.983 INFO (qtp834133664-19) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=63
2018-09-22 05:58:54.820 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy
Starting Replication Recovery.
2018-09-22 05:58:54.820 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy
Attempting to replicate from
[http://server61:8080/solr/COLL_shard8_replica1/].
2018-09-22 05:58:54.967 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Master's
generation: 51971
2018-09-22 05:58:54.967 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Master's
version: 1537595934827
2018-09-22 05:58:54.967 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Slave's
generation: 1
2018-09-22 05:58:54.967 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Slave's
version: 0
2018-09-22 05:58:54.967 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Starting
replication process
2018-09-22 05:58:55.018 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Number of
files in latest index in master: 173
2018-09-22 05:58:55.019 INFO
(recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Starting
download (fullCopy=true) to
NRTCachingDirectory(MMapDirectory@/app/solr/data/COLL_shard8_replica2/data/index.20180922055855018
lockFactory=org.apache.lucene.store.NativeFSLockFactory@74255cc4;
maxCacheMB=48.0 maxMergeSizeMB=4.0)
2018-09-22 05:59:03.590 INFO (qtp834133664-15) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=0
2018-09-22 05:59:03.781 INFO (qtp834133664-21) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=25
2018-09-22 05:59:04.061 INFO (qtp834133664-22) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=52
2018-09-22 05:59:13.125 INFO (qtp834133664-13) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=42
2018-09-22 05:59:13.672 INFO (qtp834133664-20) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=2
2018-09-22 05:59:13.812 INFO (qtp834133664-21) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=9
2018-09-22 05:59:23.229 INFO (qtp834133664-19) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=43
2018-09-22 05:59:23.275 INFO (qtp834133664-15) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=18
2018-09-22 05:59:23.732 INFO (qtp834133664-20) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=3
2018-09-22 05:59:23.915 INFO (qtp834133664-21) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=18
2018-09-22 05:59:33.390 INFO (qtp834133664-22) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=89
2018-09-22 05:59:33.778 INFO (qtp834133664-20) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=0
2018-09-22 05:59:33.958 INFO (qtp834133664-21) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=19
2018-09-22 05:59:43.461 INFO (qtp834133664-13) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=46
2018-09-22 05:59:43.862 INFO (qtp834133664-20) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=2
2018-09-22 05:59:44.009 INFO (qtp834133664-21) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=15
2018-09-22 05:59:53.515 INFO (qtp834133664-19) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=24
2018-09-22 05:59:53.915 INFO (qtp834133664-20) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=4
2018-09-22 05:59:54.075 INFO (qtp834133664-21) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=15
2018-09-22 06:00:03.177 INFO (qtp834133664-15) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=21
2018-09-22 06:00:03.596 INFO (qtp834133664-22) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=51
2018-09-22 06:00:03.977 INFO (qtp834133664-20) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=12
2018-09-22 06:00:13.207 INFO (qtp834133664-21) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=4
2018-09-22 06:00:13.685 INFO (qtp834133664-13) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=65
2018-09-22 06:00:13.686 ERROR (Finalizer) [ ]
o.a.s.u.SolrIndexWriter SolrIndexWriter was not closed prior to
finalize(), indicates a bug -- POSSIBLE RESOURCE LEAK!!!
2018-09-22 06:00:13.686 ERROR (Finalizer) [ ]
o.a.s.u.SolrIndexWriter Error closing IndexWriter
java.lang.NullPointerException
at org.apache.lucene.index.IndexWriter.doFlush(IndexWriter.java:3414)
at org.apache.lucene.index.IndexWriter.flush(IndexWriter.java:3376)
at org.apache.lucene.index.IndexWriter.shutdown(IndexWriter.java:1126)
at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1171)
at org.apache.solr.update.SolrIndexWriter.close(SolrIndexWriter.java:278)
at org.apache.solr.update.SolrIndexWriter.finalize(SolrIndexWriter.java:334)
at java.lang.System$2.invokeFinalize(System.java:1270)
at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:98)
at java.lang.ref.Finalizer.access$100(Finalizer.java:34)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:210)
2018-09-22 06:00:13.686 ERROR (Finalizer) [ ]
o.a.s.u.SolrIndexWriter SolrIndexWriter was not closed prior to
finalize(), indicates a bug -- POSSIBLE RESOURCE LEAK!!!
2018-09-22 06:00:13.687 ERROR (Finalizer) [ ]
o.a.s.u.SolrIndexWriter Error closing IndexWriter
java.lang.NullPointerException
at org.apache.lucene.index.IndexWriter.doFlush(IndexWriter.java:3414)
at org.apache.lucene.index.IndexWriter.flush(IndexWriter.java:3376)
at org.apache.lucene.index.IndexWriter.shutdown(IndexWriter.java:1126)
at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1171)
at org.apache.solr.update.SolrIndexWriter.close(SolrIndexWriter.java:278)
at org.apache.solr.update.SolrIndexWriter.finalize(SolrIndexWriter.java:334)
at java.lang.System$2.invokeFinalize(System.java:1270)
at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:98)
at java.lang.ref.Finalizer.access$100(Finalizer.java:34)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:210)
2018-09-22 06:00:14.018 INFO (qtp834133664-20) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=7
2018-09-22 06:00:23.270 INFO (qtp834133664-15) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=15
2018-09-22 06:00:23.775 INFO (qtp834133664-19) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=42
2018-09-22 06:00:24.058 INFO (qtp834133664-20) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=0
2018-09-22 06:00:33.139 INFO (qtp834133664-21) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=19
2018-09-22 06:00:33.345 INFO (qtp834133664-15) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=24
2018-09-22 06:00:33.844 INFO (qtp834133664-22) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=43
2018-09-22 06:00:43.165 INFO (qtp834133664-20) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=0
2018-09-22 06:00:43.398 INFO (qtp834133664-15) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=8
2018-09-22 06:00:43.915 INFO (qtp834133664-13) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=46
2018-09-22 06:00:53.211 INFO (qtp834133664-21) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=2
2018-09-22 06:00:53.448 INFO (qtp834133664-15) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=0
2018-09-22 06:00:53.987 INFO (qtp834133664-19) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=49
2018-09-22 06:01:03.252 INFO (qtp834133664-20) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
[COLL_shard8_replica2] webapp=/solr path=/update
params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
status=0 QTime=0
Re: POSSIBLE RESOURCE LEAK- solr 6.6.2
Posted by Mikhail Khludnev <mk...@apache.org>.
I've nailed down some edge cases of ZK expiration at 7.4 under SOLR-12200.
Not sure if it may help.
On Sat, Sep 22, 2018 at 5:05 PM Susheel Kumar <su...@gmail.com> wrote:
> It looks like it got into this state of recovery after "ZooKeeper session
> was expired" and then never recovered. In what situations this warn
> message "Zookeeper session was expired" can come and how does it puts into
> recovery... Any suggestions ?
>
>
> 2018-09-19 22:48:44.945 INFO
> (searcherExecutor-7-thread-1-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.SolrCore
> [COLL_shard8_replica2] Registered new searcher
> Searcher@6d5ccad4[COLL_shard8_replica2]
>
> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_8j4y(6.6.2):C879512/181359:delGen=2713)
> Uninverting(_8z2y(6.6.2):C801846/163497:delGen=4342)
> Uninverting(_81f9(6.6.2):C774110/378113:delGen=2398)
> Uninverting(_82ll(6.6.2):C769263/348530:delGen=2427)
> Uninverting(_83ne(6.6.2):C848884/94595:delGen=2131)
> Uninverting(_4l73(6.6.2):C814472/317397:delGen=2514)
> Uninverting(_7yqo(6.6.2):C724552/169735:delGen=3154)
> Uninverting(_852r(6.6.2):C707686/75053:delGen=3037)
> Uninverting(_ejht(6.6.2):C725012/321185:delGen=3588)
> Uninverting(_gxvh(6.6.2):c432789/82230:delGen=1073)
> Uninverting(_gblg(6.6.2):c215311/112981:delGen=1780)
> Uninverting(_h8mr(6.6.2):c92526/13326:delGen=268)
> Uninverting(_h71f(6.6.2):c51823/8823:delGen=371)
> Uninverting(_h1p2(6.6.2):c58771/20717:delGen=617)
> Uninverting(_h8uz(6.6.2):c9264/2802:delGen=143)
> Uninverting(_hb7e(6.6.2):c35846/399:delGen=18)
> Uninverting(_h9m4(6.6.2):c12335/1404:delGen=111)
> Uninverting(_haiz(6.6.2):c9691/1786:delGen=67)
> Uninverting(_halr(6.6.2):c960/62:delGen=24)
> Uninverting(_hb16(6.6.2):c1196/69:delGen=12)
> Uninverting(_hb5q(6.6.2):c2112/619:delGen=6)
> Uninverting(_hb6u(6.6.2):c648/65:delGen=8)
> Uninverting(_hb74(6.6.2):c664/35:delGen=9)
> Uninverting(_hbba(6.6.2):c465/70:delGen=1)
> Uninverting(_hbcf(6.6.2):c269/1:delGen=1)
> Uninverting(_hba6(6.6.2):c504/26:delGen=3) Uninverting(_hbcq(6.6.2):c377)
> Uninverting(_hbaq(6.6.2):c248/4:delGen=4)
> Uninverting(_hbc4(6.6.2):c443/1:delGen=1)
> Uninverting(_hb90(6.6.2):C875/376:delGen=1)
> Uninverting(_hbbu(6.6.2):c431/1:delGen=1)
> Uninverting(_hbbk(6.6.2):c262/2:delGen=2)
> Uninverting(_hbcs(6.6.2):C9/1:delGen=1)
> Uninverting(_hbct(6.6.2):C7/2:delGen=1)
> Uninverting(_hbcu(6.6.2):C47/1:delGen=1)
> Uninverting(_hbcv(6.6.2):C147/1:delGen=1) Uninverting(_hbcw(6.6.2):C1)
> Uninverting(_hbcx(6.6.2):C4/2:delGen=1)
> Uninverting(_hbcy(6.6.2):C6/3:delGen=1)))}
> @
> @
> @
> @
> /recovery
> 2018-09-19 23:45:18.846 WARN
> (zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
> o.a.s.c.c.ConnectionManager Watcher
> org.apache.solr.common.cloud.ConnectionManager@28bc45b1 name:
> ZooKeeperConnection
> Watcher:zk1:2182,zk2:2182,zk3:2182,zk4:2182,zk5:2182/chroot got event
> WatchedEvent state:Disconnected type:None path:null path: null type: None
> 2018-09-19 23:45:18.846 WARN
> (zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
> o.a.s.c.c.ConnectionManager zkClient has disconnected
> 2018-09-19 23:45:19.185 INFO (commitScheduler-11-thread-1) [c:COLL
> s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.s.SolrIndexSearcher
> Opening [Searcher@711c5774[COLL_shard8_replica2] main]
> 2018-09-19 23:45:19.186 INFO (commitScheduler-11-thread-1) [c:COLL
> s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.u.DirectUpdateHandler2
> end_commit_flush
> 2018-09-19 23:45:19.496 INFO (commitScheduler-10-thread-1) [c:COLL
> s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.u.DirectUpdateHandler2
> end_commit_flush
> 2018-09-19 23:45:19.506 WARN
>
> (zkCallback-5-thread-50-processing-n:server62:8080_solr-SendThread(zk2:2182))
> [ ] o.a.z.ClientCnxn Unable to reconnect to ZooKeeper service, session
> 0x36591d677ff0003 has expired
> 2018-09-19 23:45:19.507 WARN
> (zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
> o.a.s.c.c.ConnectionManager Watcher
> org.apache.solr.common.cloud.ConnectionManager@28bc45b1 name:
> ZooKeeperConnection
> Watcher:zk1:2182,zk2:2182,zk3:2182,zk4:2182,zk5:2182/chroot got event
> WatchedEvent state:Expired type:None path:null path: null type: None
> 2018-09-19 23:45:19.507 WARN
> (zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
> o.a.s.c.c.ConnectionManager Our previous ZooKeeper session was expired.
> Attempting to reconnect to recover relationship with ZooKeeper...
> 2018-09-19 23:45:19.507 WARN
> (zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
> o.a.s.c.c.DefaultConnectionStrategy Connection expired - starting a new
> one...
> 2018-09-19 23:45:19.518 INFO
> (zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
> o.a.s.c.c.ConnectionManager Connection with ZooKeeper reestablished.
> 2018-09-19 23:45:19.518 INFO
> (zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
> o.a.s.c.ZkController ZooKeeper session re-connected ... refreshing core
> states after session expiration.
> 2018-09-19 23:45:19.521 INFO
> (zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
> o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (16) -> (15)
> 2018-09-19 23:45:19.542 INFO
> (zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
> o.a.s.c.ZkController Replica core_node16 NOT in leader-initiated recovery,
> need to wait for leader to see down state.
> 2018-09-19 23:45:19.605 INFO
> (zkCallback-5-thread-89-processing-n:server62:8080_solr) [ ]
> o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
> state:SyncConnected type:NodeDataChanged
> path:/collections/COLLP/state.json] for collection [COLLP] has occurred -
> updating... (live nodes size: [15])
> 2018-09-19 23:45:19.754 INFO
> (zkCallback-5-thread-89-processing-n:server62:8080_solr) [ ]
> o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
> state:SyncConnected type:NodeDataChanged path:/collections/COLL/state.json]
> for collection [COLL] has occurred - updating... (live nodes size: [15])
> 2018-09-19 23:45:20.741 INFO
> (zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
> o.a.s.c.ZkController Replica core_node16 NOT in leader-initiated recovery,
> need to wait for leader to see down state.
> 2018-09-19 23:45:20.743 INFO
> (zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
> o.a.s.c.ZkController Register node as live in
> ZooKeeper:/live_nodes/server62:8080_solr
> 2018-09-19 23:45:20.747 INFO
> (zkCallback-5-thread-89-processing-n:server62:8080_solr) [ ]
> o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (15) -> (16)
> 2018-09-19 23:45:20.747 INFO
> (zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
> o.a.s.c.c.DefaultConnectionStrategy Reconnected to ZooKeeper
> 2018-09-19 23:45:20.747 INFO
> (coreZkRegister-1-thread-6-processing-n:server62:8080_solr) [ ]
> o.a.s.c.ZkController Registering core COLL_shard8_replica2 afterExpiration?
> true
> 2018-09-19 23:45:20.748 INFO
> (zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
> o.a.s.c.c.ConnectionManager Connected:true
> 2018-09-19 23:45:20.748 INFO
> (coreZkRegister-1-thread-7-processing-n:server62:8080_solr) [ ]
> o.a.s.c.ZkController Registering core COLLP_shard8_replica2
> afterExpiration? true
> 2018-09-19 23:45:20.749 INFO (Thread-57617) [ ] o.a.s.c.SolrCore config
> update listener called for core COLL_shard8_replica2
> 2018-09-19 23:45:20.751 INFO (Thread-57618) [ ] o.a.s.c.SolrCore config
> update listener called for core COLLP_shard8_replica2
> 2018-09-19 23:45:20.753 INFO (Thread-57618) [ ] o.a.s.c.SolrCore core
> reload COLLP_shard8_replica2
> 2018-09-19 23:45:20.753 INFO
> (coreZkRegister-1-thread-6-processing-n:server62:8080_solr) [c:COLL
> s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.ZkController Core
> needs to recover:COLL_shard8_replica2
> 2018-09-19 23:45:20.753 INFO
> (coreZkRegister-1-thread-7-processing-n:server62:8080_solr) [c:COLLP
> s:shard8 r:core_node16 x:COLLP_shard8_replica2] o.a.s.c.ZkController Core
> needs to recover:COLLP_shard8_replica2
> 2018-09-19 23:45:20.753 INFO
> (updateExecutor-2-thread-5-processing-n:server62:8080_solr
> x:COLLP_shard8_replica2 s:shard8 c:COLLP r:core_node16) [c:COLLP s:shard8
> r:core_node16 x:COLLP_shard8_replica2] o.a.s.u.DefaultSolrCoreState Running
> recovery
> 2018-09-19 23:45:20.753 INFO
> (updateExecutor-2-thread-5-processing-n:server62:8080_solr
> x:COLLP_shard8_replica2 s:shard8 c:COLLP r:core_node16) [c:COLLP s:shard8
> r:core_node16 x:COLLP_shard8_replica2] o.a.s.c.ActionThrottle The last
> recovery attempt started 1026739687ms ago.
> 2018-09-19 23:45:20.764 INFO (Thread-57618) [ ] o.a.s.c.RequestParams
> conf resource params.json loaded . version : 0
> 2018-09-19 23:45:20.764 INFO (Thread-57618) [ ] o.a.s.c.RequestParams
> request params refreshed to version 0
> 2018-09-19 23:45:20.765 INFO (Thread-57618) [ ]
> o.a.s.c.SolrResourceLoader [COLLP_shard8_replica2] Added 55 libs to
> classloader, from paths: [/opt/solr/contrib/clustering/lib,
> /opt/solr/contrib/extraction/lib, /opt/solr/contrib/langid/lib,
> /opt/solr/contrib/velocity/lib, /opt/solr/dist]
> 2018-09-19 23:45:20.789 INFO
> (recoveryExecutor-3-thread-5-processing-n:server62:8080_solr
> x:COLLP_shard8_replica2 s:shard8 c:COLLP r:core_node16) [c:COLLP s:shard8
> r:core_node16 x:COLLP_shard8_replica2] o.a.s.c.RecoveryStrategy Starting
> recovery process. recoveringAfterStartup=false
> 2018-09-19 23:45:20.792 INFO
> (updateExecutor-2-thread-6-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.u.DefaultSolrCoreState Running
> recovery
> 2018-09-19 23:45:20.792 INFO
> (updateExecutor-2-thread-6-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.ActionThrottle The last
> recovery attempt started 1398949248ms ago.
> 2018-09-19 23:45:20.792 INFO
> (recoveryExecutor-3-thread-6-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Starting
> recovery process. recoveringAfterStartup=false
> 2018-09-19 23:45:20.792 INFO
> (recoveryExecutor-3-thread-5-processing-n:server62:8080_solr
> x:COLLP_shard8_replica2 s:shard8 c:COLLP r:core_node16) [c:COLLP s:shard8
> r:core_node16 x:COLLP_shard8_replica2] o.a.s.c.RecoveryStrategy Begin
> buffering updates. core=[COLLP_shard8_replica2]
> 2018-09-19 23:45:20.792 INFO
> (recoveryExecutor-3-thread-5-processing-n:server62:8080_solr
> x:COLLP_shard8_replica2 s:shard8 c:COLLP r:core_node16) [c:COLLP s:shard8
> r:core_node16 x:COLLP_shard8_replica2] o.a.s.u.UpdateLog Starting to buffer
> updates. FSUpdateLog{state=ACTIVE, tlog=null}
> 2018-09-19 23:45:20.792 INFO
> (recoveryExecutor-3-thread-5-processing-n:server62:8080_solr
> x:COLLP_shard8_replica2 s:shard8 c:COLLP r:core_node16) [c:COLLP s:shard8
> r:core_node16 x:COLLP_shard8_replica2] o.a.s.c.RecoveryStrategy Publishing
> state of core [COLLP_shard8_replica2] as recovering, leader is [
> http://server61:8080/solr/COLLP_shard8_replica1/] and I am [
> http://server62:8080/solr/COLLP_shard8_replica2/]
> 2018-09-19 23:45:20.832 INFO
> (recoveryExecutor-3-thread-5-processing-n:server62:8080_solr
> x:COLLP_shard8_replica2 s:shard8 c:COLLP r:core_node16) [c:COLLP s:shard8
> r:core_node16 x:COLLP_shard8_replica2] o.a.s.c.RecoveryStrategy Sending
> prep recovery command to [http://server61:8080/solr]; [WaitForState:
>
> action=PREPRECOVERY&core=COLLP_shard8_replica1&nodeName=server62:8080_solr&coreNodeName=core_node16&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
> 2018-09-19 23:45:20.861 INFO (Thread-57618) [ ] o.a.s.u.SolrIndexConfig
> IndexWriter infoStream solr logging is enabled
> 2018-09-19 23:45:20.863 INFO (Thread-57618) [ ] o.a.s.c.SolrConfig Using
> Lucene MatchVersion: 6.6.2
> 2018-09-19 23:45:20.924 INFO (Thread-57618) [ ] o.a.s.s.IndexSchema
> [COLLP_shard8_replica2] Schema name=COLLP
> 2018-09-19 23:45:20.931 INFO
> (zkCallback-5-thread-89-processing-n:server62:8080_solr) [ ]
> o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
> state:SyncConnected type:NodeDataChanged
> path:/collections/COLLP/state.json] for collection [COLLP] has occurred -
> updating... (live nodes size: [16])
> 2018-09-19 23:45:21.075 INFO
> (recoveryExecutor-3-thread-6-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Begin
> buffering updates. core=[COLL_shard8_replica2]
> 2018-09-19 23:45:21.075 INFO
> (recoveryExecutor-3-thread-6-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.u.UpdateLog Starting to buffer
> updates. FSUpdateLog{state=ACTIVE,
>
> tlog=tlog{file=/app/solr/data/COLL_shard8_replica2/data/tlog/tlog.0000000000000051065.1612081196978667520
> refcount=1}}
> 2018-09-19 23:45:21.075 INFO
> (recoveryExecutor-3-thread-6-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Publishing
> state of core [COLL_shard8_replica2] as recovering, leader is [
> http://server61:8080/solr/COLL_shard8_replica1/] and I am [
> http://server62:8080/solr/COLL_shard8_replica2/]
> 2018-09-19 23:45:21.079 INFO
> (recoveryExecutor-3-thread-6-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Sending prep
> recovery command to [http://server61:8080/solr]; [WaitForState:
>
> action=PREPRECOVERY&core=COLL_shard8_replica1&nodeName=server62:8080_solr&coreNodeName=core_node16&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
> 2018-09-19 23:45:21.084 INFO
> (searcherExecutor-7-thread-1-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.QuerySenderListener
> QuerySenderListener sending requests to Searcher@711c5774
> [COLL_shard8_replica2]
>
> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_8j4y(6.6.2):C879512/181368:delGen=2714)
> Uninverting(_8z2y(6.6.2):C801846/163505:delGen=4343)
> Uninverting(_81f9(6.6.2):C774110/378113:delGen=2398)
> Uninverting(_82ll(6.6.2):C769263/348530:delGen=2427)
> Uninverting(_83ne(6.6.2):C848884/94597:delGen=2133)
> Uninverting(_4l73(6.6.2):C814472/317397:delGen=2514)
> Uninverting(_7yqo(6.6.2):C724552/169736:delGen=3155)
> Uninverting(_852r(6.6.2):C707686/75054:delGen=3038)
> Uninverting(_ejht(6.6.2):C725012/321262:delGen=3591)
> Uninverting(_gxvh(6.6.2):c432789/82761:delGen=1078)
> Uninverting(_gblg(6.6.2):c215311/113006:delGen=1782)
> Uninverting(_h8mr(6.6.2):c92526/14080:delGen=277)
> Uninverting(_h71f(6.6.2):c51823/8823:delGen=371)
> Uninverting(_h1p2(6.6.2):c58771/20719:delGen=618)
> Uninverting(_h8uz(6.6.2):c9264/2802:delGen=143)
> Uninverting(_hb7e(6.6.2):c35846/429:delGen=27)
> Uninverting(_h9m4(6.6.2):c12335/1407:delGen=114)
> Uninverting(_haiz(6.6.2):c9691/1789:delGen=68)
> Uninverting(_halr(6.6.2):c960/340:delGen=25)
> Uninverting(_hb16(6.6.2):c1196/69:delGen=12)
> Uninverting(_hb5q(6.6.2):c2112/867:delGen=7)
> Uninverting(_hb6u(6.6.2):c648/65:delGen=8)
> Uninverting(_hb74(6.6.2):c664/36:delGen=10)
> Uninverting(_hbba(6.6.2):c465/72:delGen=3)
> Uninverting(_hbd1(6.6.2):c1224/1:delGen=1)
> Uninverting(_hba6(6.6.2):c504/31:delGen=6)
> Uninverting(_hbcq(6.6.2):c377/1:delGen=1)
> Uninverting(_hbe7(6.6.2):c2163/1:delGen=1)
> Uninverting(_hbdx(6.6.2):c506/3:delGen=1)
> Uninverting(_hbfl(6.6.2):c71/1:delGen=1)
> Uninverting(_hbfb(6.6.2):c62/1:delGen=1)
> Uninverting(_hbed(6.6.2):C206/3:delGen=1)
> Uninverting(_hbfm(6.6.2):C6/2:delGen=1)
> Uninverting(_hbfn(6.6.2):C560/281:delGen=2)
> Uninverting(_hbfo(6.6.2):C12/7:delGen=1)
> Uninverting(_hbfp(6.6.2):C4/2:delGen=1)
> Uninverting(_hbfq(6.6.2):C4/2:delGen=1)
> Uninverting(_hbfs(6.6.2):C9/5:delGen=1)))}
> 2018-09-19 23:45:21.084 INFO
> (searcherExecutor-7-thread-1-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.QuerySenderListener
> QuerySenderListener done.
> 2018-09-19 23:45:21.084 INFO
> (searcherExecutor-7-thread-1-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.SolrCore
> [COLL_shard8_replica2] Registered new searcher
> Searcher@711c5774[COLL_shard8_replica2]
>
> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_8j4y(6.6.2):C879512/181368:delGen=2714)
> Uninverting(_8z2y(6.6.2):C801846/163505:delGen=4343)
> Uninverting(_81f9(6.6.2):C774110/378113:delGen=2398)
> Uninverting(_82ll(6.6.2):C769263/348530:delGen=2427)
> Uninverting(_83ne(6.6.2):C848884/94597:delGen=2133)
> Uninverting(_4l73(6.6.2):C814472/317397:delGen=2514)
> Uninverting(_7yqo(6.6.2):C724552/169736:delGen=3155)
> Uninverting(_852r(6.6.2):C707686/75054:delGen=3038)
> Uninverting(_ejht(6.6.2):C725012/321262:delGen=3591)
> Uninverting(_gxvh(6.6.2):c432789/82761:delGen=1078)
> Uninverting(_gblg(6.6.2):c215311/113006:delGen=1782)
> Uninverting(_h8mr(6.6.2):c92526/14080:delGen=277)
> Uninverting(_h71f(6.6.2):c51823/8823:delGen=371)
> Uninverting(_h1p2(6.6.2):c58771/20719:delGen=618)
> Uninverting(_h8uz(6.6.2):c9264/2802:delGen=143)
> Uninverting(_hb7e(6.6.2):c35846/429:delGen=27)
> Uninverting(_h9m4(6.6.2):c12335/1407:delGen=114)
> Uninverting(_haiz(6.6.2):c9691/1789:delGen=68)
> Uninverting(_halr(6.6.2):c960/340:delGen=25)
> Uninverting(_hb16(6.6.2):c1196/69:delGen=12)
> Uninverting(_hb5q(6.6.2):c2112/867:delGen=7)
> Uninverting(_hb6u(6.6.2):c648/65:delGen=8)
> Uninverting(_hb74(6.6.2):c664/36:delGen=10)
> Uninverting(_hbba(6.6.2):c465/72:delGen=3)
> Uninverting(_hbd1(6.6.2):c1224/1:delGen=1)
> Uninverting(_hba6(6.6.2):c504/31:delGen=6)
> Uninverting(_hbcq(6.6.2):c377/1:delGen=1)
> Uninverting(_hbe7(6.6.2):c2163/1:delGen=1)
> Uninverting(_hbdx(6.6.2):c506/3:delGen=1)
> Uninverting(_hbfl(6.6.2):c71/1:delGen=1)
> Uninverting(_hbfb(6.6.2):c62/1:delGen=1)
> Uninverting(_hbed(6.6.2):C206/3:delGen=1)
> Uninverting(_hbfm(6.6.2):C6/2:delGen=1)
> Uninverting(_hbfn(6.6.2):C560/281:delGen=2)
> Uninverting(_hbfo(6.6.2):C12/7:delGen=1)
> Uninverting(_hbfp(6.6.2):C4/2:delGen=1)
> Uninverting(_hbfq(6.6.2):C4/2:delGen=1)
> Uninverting(_hbfs(6.6.2):C9/5:delGen=1)))}
>
> On Sat, Sep 22, 2018 at 2:20 AM Susheel Kumar <su...@gmail.com>
> wrote:
>
> > Hello,
> >
> > I noticed one of the replica's in Recover Failed status and after trying
> > to recreate the replica/restart the node to recover, I see below error
> from
> > solr log. The leader for this shard8 replica2 i.e. replica1@server 61
> > seems to be fine and serving the queries.
> >
> > What does this indicate "SolrIndexWriter was not closed prior to
> > finalize(), indicates a bug -- POSSIBLE RESOURCE LEAK!!!" from below log.
> >
> > 2018-09-22 06:00:13.686 ERROR (Finalizer) [ ] o.a.s.u.SolrIndexWriter
> Error closing IndexWriter2018-09-22 05:58:13.409 INFO (qtp834133664-21)
> [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=5
> > 2018-09-22 05:58:13.686 INFO (qtp834133664-19) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=39
> > 2018-09-22 05:58:19.338 ERROR
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.ReplicationHandler Index
> fetch failed :org.apache.solr.common.SolrException: Index fetch failed :
> > at
> org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:598)
> > at
> org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:301)
> > at
> org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:400)
> > at
> org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:219)
> > at
> org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:471)
> > at
> org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:284)
> > at
> com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
> > 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:1149)
> > at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> > at java.lang.Thread.run(Thread.java:748)
> > Caused by: org.apache.lucene.index.CorruptIndexException: codec header
> mismatch: actual header=1997958933 vs expected header=1071082519
> (resource=BufferedChecksumIndexInput(MMapIndexInput(path="/app/solr/data/COLL_shard8_replica2/data/index/_8ktm.fnm")))
> > at
> org.apache.lucene.codecs.CodecUtil.checkHeader(CodecUtil.java:196)
> > at
> org.apache.lucene.codecs.CodecUtil.checkIndexHeader(CodecUtil.java:255)
> > at
> org.apache.lucene.codecs.lucene60.Lucene60FieldInfosFormat.read(Lucene60FieldInfosFormat.java:117)
> > at
> org.apache.lucene.index.IndexWriter.readFieldInfos(IndexWriter.java:1063)
> > at
> org.apache.lucene.index.IndexWriter.getFieldNumberMap(IndexWriter.java:1075)
> > at
> org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:960)
> > at
> org.apache.solr.update.SolrIndexWriter.<init>(SolrIndexWriter.java:118)
> > at
> org.apache.solr.update.SolrIndexWriter.create(SolrIndexWriter.java:93)
> > at
> org.apache.solr.update.DefaultSolrCoreState.createMainIndexWriter(DefaultSolrCoreState.java:257)
> > at
> org.apache.solr.update.DefaultSolrCoreState.changeWriter(DefaultSolrCoreState.java:220)
> > at
> org.apache.solr.update.DefaultSolrCoreState.openIndexWriter(DefaultSolrCoreState.java:245)
> > at
> org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:551)
> > ... 12 more
> > Suppressed: org.apache.lucene.index.CorruptIndexException:
> checksum failed (hardware problem?) : expected=e42fdf3e actual=c0432e62
> (resource=BufferedChecksumIndexInput(MMapIndexInput(path="/app/solr/data/COLL_shard8_replica2/data/index/_8ktm.fnm")))
> > at
> org.apache.lucene.codecs.CodecUtil.checkFooter(CodecUtil.java:419)
> > at
> org.apache.lucene.codecs.CodecUtil.checkFooter(CodecUtil.java:462)
> > at
> org.apache.lucene.codecs.lucene60.Lucene60FieldInfosFormat.read(Lucene60FieldInfosFormat.java:171)
> > ... 21 more
> >
> > 2018-09-22 05:58:19.338 ERROR
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Error while
> trying to recover:org.apache.solr.common.SolrException: Replication for
> recovery failed.
> > at
> org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:222)
> > at
> org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:471)
> > at
> org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:284)
> > at
> com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
> > 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:1149)
> > at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> > at java.lang.Thread.run(Thread.java:748)
> >
> > 2018-09-22 05:58:19.338 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Replay not
> started, or was not successful... still buffering updates.
> > 2018-09-22 05:58:19.338 ERROR
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Recovery
> failed - trying again... (0)
> > 2018-09-22 05:58:19.338 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Wait [2.0]
> seconds before trying to recover again (attempt=1)
> > 2018-09-22 05:58:23.352 INFO (qtp834133664-20) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=0
> > 2018-09-22 05:58:23.486 INFO (qtp834133664-21) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=18
> > 2018-09-22 05:58:23.763 INFO (qtp834133664-22) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=53
> > 2018-09-22 05:58:29.339 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Begin
> buffering updates. core=[COLL_shard8_replica2]
> > 2018-09-22 05:58:29.339 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.u.UpdateLog Restarting
> buffering. previous=RecoveryInfo{adds=0 deletes=0 deleteByQuery=0 errors=0
> positionOfStart=0}
> > 2018-09-22 05:58:29.339 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.u.UpdateLog Starting to buffer
> updates. FSUpdateLog{state=BUFFERING,
> tlog=tlog{file=/app/solr/data/COLL_shard8_replica2/data/tlog/tlog.0000000000000000000.1612285920588857344
> refcount=2}}
> > 2018-09-22 05:58:29.339 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Publishing
> state of core [COLL_shard8_replica2] as recovering, leader is [
> http://server61:8080/solr/COLL_shard8_replica1/] and I am [
> http://server62:8080/solr/COLL_shard8_replica2/]
> > 2018-09-22 05:58:29.343 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Sending prep
> recovery command to [http://server61:8080/solr]; [WaitForState:
> action=PREPRECOVERY&core=COLL_shard8_replica1&nodeName=server62:8080_solr&coreNodeName=core_node16&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
> > 2018-09-22 05:58:29.351 INFO
> (zkCallback-5-thread-23-processing-n:server62:8080_solr) [ ]
> o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
> state:SyncConnected type:NodeDataChanged path:/collections/COLL/state.json]
> for collection [COLL] has occurred - updating... (live nodes size: [16])
> > 2018-09-22 05:58:31.846 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Starting
> Replication Recovery.
> > 2018-09-22 05:58:31.846 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Attempting
> to replicate from [http://server61:8080/solr/COLL_shard8_replica1/].
> > 2018-09-22 05:58:32.234 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Master's
> generation: 51970
> > 2018-09-22 05:58:32.234 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Master's
> version: 1537595911854
> > 2018-09-22 05:58:32.234 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Slave's
> generation: 1
> > 2018-09-22 05:58:32.234 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Slave's version:
> 0
> > 2018-09-22 05:58:32.234 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Starting
> replication process
> > 2018-09-22 05:58:32.290 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Number of files
> in latest index in master: 257
> > 2018-09-22 05:58:32.309 ERROR
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.ReplicationHandler Index
> fetch failed :org.apache.solr.common.SolrException: Index fetch failed :
> > at
> org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:598)
> > at
> org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:301)
> > at
> org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:400)
> > at
> org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:219)
> > at
> org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:471)
> > at
> org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:284)
> > at
> com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
> > 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:1149)
> > at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> > at java.lang.Thread.run(Thread.java:748)
> > Caused by: org.apache.lucene.index.CorruptIndexException: codec header
> mismatch: actual header=1997958933 vs expected header=1071082519
> (resource=BufferedChecksumIndexInput(MMapIndexInput(path="/app/solr/data/COLL_shard8_replica2/data/index/_8ktm.fnm")))
> > at
> org.apache.lucene.codecs.CodecUtil.checkHeader(CodecUtil.java:196)
> > at
> org.apache.lucene.codecs.CodecUtil.checkIndexHeader(CodecUtil.java:255)
> > at
> org.apache.lucene.codecs.lucene60.Lucene60FieldInfosFormat.read(Lucene60FieldInfosFormat.java:117)
> > at
> org.apache.lucene.index.IndexWriter.readFieldInfos(IndexWriter.java:1063)
> > at
> org.apache.lucene.index.IndexWriter.getFieldNumberMap(IndexWriter.java:1075)
> > at
> org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:960)
> > at
> org.apache.solr.update.SolrIndexWriter.<init>(SolrIndexWriter.java:118)
> > at
> org.apache.solr.update.SolrIndexWriter.create(SolrIndexWriter.java:93)
> > at
> org.apache.solr.update.DefaultSolrCoreState.createMainIndexWriter(DefaultSolrCoreState.java:257)
> > at
> org.apache.solr.update.DefaultSolrCoreState.changeWriter(DefaultSolrCoreState.java:220)
> > at
> org.apache.solr.update.DefaultSolrCoreState.newIndexWriter(DefaultSolrCoreState.java:229)
> > at
> org.apache.solr.update.DirectUpdateHandler2.newIndexWriter(DirectUpdateHandler2.java:726)
> > at
> org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:457)
> > ... 12 more
> > Suppressed: org.apache.lucene.index.CorruptIndexException:
> checksum failed (hardware problem?) : expected=e42fdf3e actual=c0432e62
> (resource=BufferedChecksumIndexInput(MMapIndexInput(path="/app/solr/data/COLL_shard8_replica2/data/index/_8ktm.fnm")))
> > at
> org.apache.lucene.codecs.CodecUtil.checkFooter(CodecUtil.java:419)
> > at
> org.apache.lucene.codecs.CodecUtil.checkFooter(CodecUtil.java:462)
> > at
> org.apache.lucene.codecs.lucene60.Lucene60FieldInfosFormat.read(Lucene60FieldInfosFormat.java:171)
> > ... 22 more
> >
> > 2018-09-22 05:58:32.309 ERROR
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Error while
> trying to recover:org.apache.solr.common.SolrException: Replication for
> recovery failed.
> > at
> org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:222)
> > at
> org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:471)
> > at
> org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:284)
> > at
> com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
> > 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:1149)
> > at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> > at java.lang.Thread.run(Thread.java:748)
> >
> > 2018-09-22 05:58:32.310 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Replay not
> started, or was not successful... still buffering updates.
> > 2018-09-22 05:58:32.310 ERROR
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Recovery
> failed - trying again... (1)
> > 2018-09-22 05:58:32.310 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Wait [4.0]
> seconds before trying to recover again (attempt=2)
> > 2018-09-22 05:58:33.423 INFO (qtp834133664-15) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=4
> > 2018-09-22 05:58:33.548 INFO (qtp834133664-21) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=3
> > 2018-09-22 05:58:33.834 INFO (qtp834133664-19) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=44
> > 2018-09-22 05:58:43.480 INFO (qtp834133664-13) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=2
> > 2018-09-22 05:58:43.624 INFO (qtp834133664-21) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=8
> > 2018-09-22 05:58:43.882 INFO (qtp834133664-22) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=23
> > 2018-09-22 05:58:52.310 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Begin
> buffering updates. core=[COLL_shard8_replica2]
> > 2018-09-22 05:58:52.310 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.u.UpdateLog Restarting
> buffering. previous=RecoveryInfo{adds=0 deletes=0 deleteByQuery=0 errors=0
> positionOfStart=2630296}
> > 2018-09-22 05:58:52.310 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.u.UpdateLog Starting to buffer
> updates. FSUpdateLog{state=BUFFERING,
> tlog=tlog{file=/app/solr/data/COLL_shard8_replica2/data/tlog/tlog.0000000000000000000.1612285920588857344
> refcount=2}}
> > 2018-09-22 05:58:52.310 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Publishing
> state of core [COLL_shard8_replica2] as recovering, leader is [
> http://server61:8080/solr/COLL_shard8_replica1/] and I am [
> http://server62:8080/solr/COLL_shard8_replica2/]
> > 2018-09-22 05:58:52.317 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Sending prep
> recovery command to [http://server61:8080/solr]; [WaitForState:
> action=PREPRECOVERY&core=COLL_shard8_replica1&nodeName=server62:8080_solr&coreNodeName=core_node16&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
> > 2018-09-22 05:58:52.325 INFO
> (zkCallback-5-thread-23-processing-n:server62:8080_solr) [ ]
> o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
> state:SyncConnected type:NodeDataChanged path:/collections/COLL/state.json]
> for collection [COLL] has occurred - updating... (live nodes size: [16])
> > 2018-09-22 05:58:53.538 INFO (qtp834133664-20) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=8
> > 2018-09-22 05:58:53.679 INFO (qtp834133664-21) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=4
> > 2018-09-22 05:58:53.983 INFO (qtp834133664-19) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=63
> > 2018-09-22 05:58:54.820 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Starting
> Replication Recovery.
> > 2018-09-22 05:58:54.820 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Attempting
> to replicate from [http://server61:8080/solr/COLL_shard8_replica1/].
> > 2018-09-22 05:58:54.967 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Master's
> generation: 51971
> > 2018-09-22 05:58:54.967 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Master's
> version: 1537595934827
> > 2018-09-22 05:58:54.967 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Slave's
> generation: 1
> > 2018-09-22 05:58:54.967 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Slave's version:
> 0
> > 2018-09-22 05:58:54.967 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Starting
> replication process
> > 2018-09-22 05:58:55.018 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Number of files
> in latest index in master: 173
> > 2018-09-22 05:58:55.019 INFO
> (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr
> x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Starting
> download (fullCopy=true) to NRTCachingDirectory(MMapDirectory@/app/solr/data/COLL_shard8_replica2/data/index.20180922055855018
> lockFactory=org.apache.lucene.store.NativeFSLockFactory@74255cc4;
> maxCacheMB=48.0 maxMergeSizeMB=4.0)
> > 2018-09-22 05:59:03.590 INFO (qtp834133664-15) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=0
> > 2018-09-22 05:59:03.781 INFO (qtp834133664-21) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=25
> > 2018-09-22 05:59:04.061 INFO (qtp834133664-22) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=52
> > 2018-09-22 05:59:13.125 INFO (qtp834133664-13) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=42
> > 2018-09-22 05:59:13.672 INFO (qtp834133664-20) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=2
> > 2018-09-22 05:59:13.812 INFO (qtp834133664-21) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=9
> > 2018-09-22 05:59:23.229 INFO (qtp834133664-19) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=43
> > 2018-09-22 05:59:23.275 INFO (qtp834133664-15) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=18
> > 2018-09-22 05:59:23.732 INFO (qtp834133664-20) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=3
> > 2018-09-22 05:59:23.915 INFO (qtp834133664-21) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=18
> > 2018-09-22 05:59:33.390 INFO (qtp834133664-22) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=89
> > 2018-09-22 05:59:33.778 INFO (qtp834133664-20) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=0
> > 2018-09-22 05:59:33.958 INFO (qtp834133664-21) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=19
> > 2018-09-22 05:59:43.461 INFO (qtp834133664-13) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=46
> > 2018-09-22 05:59:43.862 INFO (qtp834133664-20) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=2
> > 2018-09-22 05:59:44.009 INFO (qtp834133664-21) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=15
> > 2018-09-22 05:59:53.515 INFO (qtp834133664-19) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=24
> > 2018-09-22 05:59:53.915 INFO (qtp834133664-20) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=4
> > 2018-09-22 05:59:54.075 INFO (qtp834133664-21) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=15
> > 2018-09-22 06:00:03.177 INFO (qtp834133664-15) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=21
> > 2018-09-22 06:00:03.596 INFO (qtp834133664-22) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=51
> > 2018-09-22 06:00:03.977 INFO (qtp834133664-20) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=12
> > 2018-09-22 06:00:13.207 INFO (qtp834133664-21) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=4
> > 2018-09-22 06:00:13.685 INFO (qtp834133664-13) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=65
> > 2018-09-22 06:00:13.686 ERROR (Finalizer) [ ] o.a.s.u.SolrIndexWriter
> SolrIndexWriter was not closed prior to finalize(), indicates a bug --
> POSSIBLE RESOURCE LEAK!!!
> > 2018-09-22 06:00:13.686 ERROR (Finalizer) [ ] o.a.s.u.SolrIndexWriter
> Error closing IndexWriter
> > java.lang.NullPointerException
> > at
> org.apache.lucene.index.IndexWriter.doFlush(IndexWriter.java:3414)
> > at
> org.apache.lucene.index.IndexWriter.flush(IndexWriter.java:3376)
> > at
> org.apache.lucene.index.IndexWriter.shutdown(IndexWriter.java:1126)
> > at
> org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1171)
> > at
> org.apache.solr.update.SolrIndexWriter.close(SolrIndexWriter.java:278)
> > at
> org.apache.solr.update.SolrIndexWriter.finalize(SolrIndexWriter.java:334)
> > at java.lang.System$2.invokeFinalize(System.java:1270)
> > at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:98)
> > at java.lang.ref.Finalizer.access$100(Finalizer.java:34)
> > at
> java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:210)
> > 2018-09-22 06:00:13.686 ERROR (Finalizer) [ ] o.a.s.u.SolrIndexWriter
> SolrIndexWriter was not closed prior to finalize(), indicates a bug --
> POSSIBLE RESOURCE LEAK!!!
> > 2018-09-22 06:00:13.687 ERROR (Finalizer) [ ] o.a.s.u.SolrIndexWriter
> Error closing IndexWriter
> > java.lang.NullPointerException
> > at
> org.apache.lucene.index.IndexWriter.doFlush(IndexWriter.java:3414)
> > at
> org.apache.lucene.index.IndexWriter.flush(IndexWriter.java:3376)
> > at
> org.apache.lucene.index.IndexWriter.shutdown(IndexWriter.java:1126)
> > at
> org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1171)
> > at
> org.apache.solr.update.SolrIndexWriter.close(SolrIndexWriter.java:278)
> > at
> org.apache.solr.update.SolrIndexWriter.finalize(SolrIndexWriter.java:334)
> > at java.lang.System$2.invokeFinalize(System.java:1270)
> > at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:98)
> > at java.lang.ref.Finalizer.access$100(Finalizer.java:34)
> > at
> java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:210)
> > 2018-09-22 06:00:14.018 INFO (qtp834133664-20) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=7
> > 2018-09-22 06:00:23.270 INFO (qtp834133664-15) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=15
> > 2018-09-22 06:00:23.775 INFO (qtp834133664-19) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=42
> > 2018-09-22 06:00:24.058 INFO (qtp834133664-20) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=0
> > 2018-09-22 06:00:33.139 INFO (qtp834133664-21) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=19
> > 2018-09-22 06:00:33.345 INFO (qtp834133664-15) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=24
> > 2018-09-22 06:00:33.844 INFO (qtp834133664-22) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=43
> > 2018-09-22 06:00:43.165 INFO (qtp834133664-20) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=0
> > 2018-09-22 06:00:43.398 INFO (qtp834133664-15) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=8
> > 2018-09-22 06:00:43.915 INFO (qtp834133664-13) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=46
> > 2018-09-22 06:00:53.211 INFO (qtp834133664-21) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=2
> > 2018-09-22 06:00:53.448 INFO (qtp834133664-15) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=0
> > 2018-09-22 06:00:53.987 INFO (qtp834133664-19) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=49
> > 2018-09-22 06:01:03.252 INFO (qtp834133664-20) [c:COLL s:shard8
> r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request
> [COLL_shard8_replica2] webapp=/solr path=/update
> params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=
> http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2}
> status=0 QTime=0
> >
> >
> >
> >
>
--
Sincerely yours
Mikhail Khludnev
Re: POSSIBLE RESOURCE LEAK- solr 6.6.2
Posted by Susheel Kumar <su...@gmail.com>.
It looks like it got into this state of recovery after "ZooKeeper session
was expired" and then never recovered. In what situations this warn
message "Zookeeper session was expired" can come and how does it puts into
recovery... Any suggestions ?
2018-09-19 22:48:44.945 INFO
(searcherExecutor-7-thread-1-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.SolrCore
[COLL_shard8_replica2] Registered new searcher
Searcher@6d5ccad4[COLL_shard8_replica2]
main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_8j4y(6.6.2):C879512/181359:delGen=2713)
Uninverting(_8z2y(6.6.2):C801846/163497:delGen=4342)
Uninverting(_81f9(6.6.2):C774110/378113:delGen=2398)
Uninverting(_82ll(6.6.2):C769263/348530:delGen=2427)
Uninverting(_83ne(6.6.2):C848884/94595:delGen=2131)
Uninverting(_4l73(6.6.2):C814472/317397:delGen=2514)
Uninverting(_7yqo(6.6.2):C724552/169735:delGen=3154)
Uninverting(_852r(6.6.2):C707686/75053:delGen=3037)
Uninverting(_ejht(6.6.2):C725012/321185:delGen=3588)
Uninverting(_gxvh(6.6.2):c432789/82230:delGen=1073)
Uninverting(_gblg(6.6.2):c215311/112981:delGen=1780)
Uninverting(_h8mr(6.6.2):c92526/13326:delGen=268)
Uninverting(_h71f(6.6.2):c51823/8823:delGen=371)
Uninverting(_h1p2(6.6.2):c58771/20717:delGen=617)
Uninverting(_h8uz(6.6.2):c9264/2802:delGen=143)
Uninverting(_hb7e(6.6.2):c35846/399:delGen=18)
Uninverting(_h9m4(6.6.2):c12335/1404:delGen=111)
Uninverting(_haiz(6.6.2):c9691/1786:delGen=67)
Uninverting(_halr(6.6.2):c960/62:delGen=24)
Uninverting(_hb16(6.6.2):c1196/69:delGen=12)
Uninverting(_hb5q(6.6.2):c2112/619:delGen=6)
Uninverting(_hb6u(6.6.2):c648/65:delGen=8)
Uninverting(_hb74(6.6.2):c664/35:delGen=9)
Uninverting(_hbba(6.6.2):c465/70:delGen=1)
Uninverting(_hbcf(6.6.2):c269/1:delGen=1)
Uninverting(_hba6(6.6.2):c504/26:delGen=3) Uninverting(_hbcq(6.6.2):c377)
Uninverting(_hbaq(6.6.2):c248/4:delGen=4)
Uninverting(_hbc4(6.6.2):c443/1:delGen=1)
Uninverting(_hb90(6.6.2):C875/376:delGen=1)
Uninverting(_hbbu(6.6.2):c431/1:delGen=1)
Uninverting(_hbbk(6.6.2):c262/2:delGen=2)
Uninverting(_hbcs(6.6.2):C9/1:delGen=1)
Uninverting(_hbct(6.6.2):C7/2:delGen=1)
Uninverting(_hbcu(6.6.2):C47/1:delGen=1)
Uninverting(_hbcv(6.6.2):C147/1:delGen=1) Uninverting(_hbcw(6.6.2):C1)
Uninverting(_hbcx(6.6.2):C4/2:delGen=1)
Uninverting(_hbcy(6.6.2):C6/3:delGen=1)))}
@
@
@
@
/recovery
2018-09-19 23:45:18.846 WARN
(zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
o.a.s.c.c.ConnectionManager Watcher
org.apache.solr.common.cloud.ConnectionManager@28bc45b1 name:
ZooKeeperConnection
Watcher:zk1:2182,zk2:2182,zk3:2182,zk4:2182,zk5:2182/chroot got event
WatchedEvent state:Disconnected type:None path:null path: null type: None
2018-09-19 23:45:18.846 WARN
(zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
o.a.s.c.c.ConnectionManager zkClient has disconnected
2018-09-19 23:45:19.185 INFO (commitScheduler-11-thread-1) [c:COLL
s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.s.SolrIndexSearcher
Opening [Searcher@711c5774[COLL_shard8_replica2] main]
2018-09-19 23:45:19.186 INFO (commitScheduler-11-thread-1) [c:COLL
s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.u.DirectUpdateHandler2
end_commit_flush
2018-09-19 23:45:19.496 INFO (commitScheduler-10-thread-1) [c:COLL
s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.u.DirectUpdateHandler2
end_commit_flush
2018-09-19 23:45:19.506 WARN
(zkCallback-5-thread-50-processing-n:server62:8080_solr-SendThread(zk2:2182))
[ ] o.a.z.ClientCnxn Unable to reconnect to ZooKeeper service, session
0x36591d677ff0003 has expired
2018-09-19 23:45:19.507 WARN
(zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
o.a.s.c.c.ConnectionManager Watcher
org.apache.solr.common.cloud.ConnectionManager@28bc45b1 name:
ZooKeeperConnection
Watcher:zk1:2182,zk2:2182,zk3:2182,zk4:2182,zk5:2182/chroot got event
WatchedEvent state:Expired type:None path:null path: null type: None
2018-09-19 23:45:19.507 WARN
(zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
o.a.s.c.c.ConnectionManager Our previous ZooKeeper session was expired.
Attempting to reconnect to recover relationship with ZooKeeper...
2018-09-19 23:45:19.507 WARN
(zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
o.a.s.c.c.DefaultConnectionStrategy Connection expired - starting a new
one...
2018-09-19 23:45:19.518 INFO
(zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
o.a.s.c.c.ConnectionManager Connection with ZooKeeper reestablished.
2018-09-19 23:45:19.518 INFO
(zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
o.a.s.c.ZkController ZooKeeper session re-connected ... refreshing core
states after session expiration.
2018-09-19 23:45:19.521 INFO
(zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (16) -> (15)
2018-09-19 23:45:19.542 INFO
(zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
o.a.s.c.ZkController Replica core_node16 NOT in leader-initiated recovery,
need to wait for leader to see down state.
2018-09-19 23:45:19.605 INFO
(zkCallback-5-thread-89-processing-n:server62:8080_solr) [ ]
o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
state:SyncConnected type:NodeDataChanged
path:/collections/COLLP/state.json] for collection [COLLP] has occurred -
updating... (live nodes size: [15])
2018-09-19 23:45:19.754 INFO
(zkCallback-5-thread-89-processing-n:server62:8080_solr) [ ]
o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
state:SyncConnected type:NodeDataChanged path:/collections/COLL/state.json]
for collection [COLL] has occurred - updating... (live nodes size: [15])
2018-09-19 23:45:20.741 INFO
(zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
o.a.s.c.ZkController Replica core_node16 NOT in leader-initiated recovery,
need to wait for leader to see down state.
2018-09-19 23:45:20.743 INFO
(zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
o.a.s.c.ZkController Register node as live in
ZooKeeper:/live_nodes/server62:8080_solr
2018-09-19 23:45:20.747 INFO
(zkCallback-5-thread-89-processing-n:server62:8080_solr) [ ]
o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (15) -> (16)
2018-09-19 23:45:20.747 INFO
(zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
o.a.s.c.c.DefaultConnectionStrategy Reconnected to ZooKeeper
2018-09-19 23:45:20.747 INFO
(coreZkRegister-1-thread-6-processing-n:server62:8080_solr) [ ]
o.a.s.c.ZkController Registering core COLL_shard8_replica2 afterExpiration?
true
2018-09-19 23:45:20.748 INFO
(zkCallback-5-thread-50-processing-n:server62:8080_solr-EventThread) [ ]
o.a.s.c.c.ConnectionManager Connected:true
2018-09-19 23:45:20.748 INFO
(coreZkRegister-1-thread-7-processing-n:server62:8080_solr) [ ]
o.a.s.c.ZkController Registering core COLLP_shard8_replica2
afterExpiration? true
2018-09-19 23:45:20.749 INFO (Thread-57617) [ ] o.a.s.c.SolrCore config
update listener called for core COLL_shard8_replica2
2018-09-19 23:45:20.751 INFO (Thread-57618) [ ] o.a.s.c.SolrCore config
update listener called for core COLLP_shard8_replica2
2018-09-19 23:45:20.753 INFO (Thread-57618) [ ] o.a.s.c.SolrCore core
reload COLLP_shard8_replica2
2018-09-19 23:45:20.753 INFO
(coreZkRegister-1-thread-6-processing-n:server62:8080_solr) [c:COLL
s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.ZkController Core
needs to recover:COLL_shard8_replica2
2018-09-19 23:45:20.753 INFO
(coreZkRegister-1-thread-7-processing-n:server62:8080_solr) [c:COLLP
s:shard8 r:core_node16 x:COLLP_shard8_replica2] o.a.s.c.ZkController Core
needs to recover:COLLP_shard8_replica2
2018-09-19 23:45:20.753 INFO
(updateExecutor-2-thread-5-processing-n:server62:8080_solr
x:COLLP_shard8_replica2 s:shard8 c:COLLP r:core_node16) [c:COLLP s:shard8
r:core_node16 x:COLLP_shard8_replica2] o.a.s.u.DefaultSolrCoreState Running
recovery
2018-09-19 23:45:20.753 INFO
(updateExecutor-2-thread-5-processing-n:server62:8080_solr
x:COLLP_shard8_replica2 s:shard8 c:COLLP r:core_node16) [c:COLLP s:shard8
r:core_node16 x:COLLP_shard8_replica2] o.a.s.c.ActionThrottle The last
recovery attempt started 1026739687ms ago.
2018-09-19 23:45:20.764 INFO (Thread-57618) [ ] o.a.s.c.RequestParams
conf resource params.json loaded . version : 0
2018-09-19 23:45:20.764 INFO (Thread-57618) [ ] o.a.s.c.RequestParams
request params refreshed to version 0
2018-09-19 23:45:20.765 INFO (Thread-57618) [ ]
o.a.s.c.SolrResourceLoader [COLLP_shard8_replica2] Added 55 libs to
classloader, from paths: [/opt/solr/contrib/clustering/lib,
/opt/solr/contrib/extraction/lib, /opt/solr/contrib/langid/lib,
/opt/solr/contrib/velocity/lib, /opt/solr/dist]
2018-09-19 23:45:20.789 INFO
(recoveryExecutor-3-thread-5-processing-n:server62:8080_solr
x:COLLP_shard8_replica2 s:shard8 c:COLLP r:core_node16) [c:COLLP s:shard8
r:core_node16 x:COLLP_shard8_replica2] o.a.s.c.RecoveryStrategy Starting
recovery process. recoveringAfterStartup=false
2018-09-19 23:45:20.792 INFO
(updateExecutor-2-thread-6-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.u.DefaultSolrCoreState Running
recovery
2018-09-19 23:45:20.792 INFO
(updateExecutor-2-thread-6-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.ActionThrottle The last
recovery attempt started 1398949248ms ago.
2018-09-19 23:45:20.792 INFO
(recoveryExecutor-3-thread-6-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Starting
recovery process. recoveringAfterStartup=false
2018-09-19 23:45:20.792 INFO
(recoveryExecutor-3-thread-5-processing-n:server62:8080_solr
x:COLLP_shard8_replica2 s:shard8 c:COLLP r:core_node16) [c:COLLP s:shard8
r:core_node16 x:COLLP_shard8_replica2] o.a.s.c.RecoveryStrategy Begin
buffering updates. core=[COLLP_shard8_replica2]
2018-09-19 23:45:20.792 INFO
(recoveryExecutor-3-thread-5-processing-n:server62:8080_solr
x:COLLP_shard8_replica2 s:shard8 c:COLLP r:core_node16) [c:COLLP s:shard8
r:core_node16 x:COLLP_shard8_replica2] o.a.s.u.UpdateLog Starting to buffer
updates. FSUpdateLog{state=ACTIVE, tlog=null}
2018-09-19 23:45:20.792 INFO
(recoveryExecutor-3-thread-5-processing-n:server62:8080_solr
x:COLLP_shard8_replica2 s:shard8 c:COLLP r:core_node16) [c:COLLP s:shard8
r:core_node16 x:COLLP_shard8_replica2] o.a.s.c.RecoveryStrategy Publishing
state of core [COLLP_shard8_replica2] as recovering, leader is [
http://server61:8080/solr/COLLP_shard8_replica1/] and I am [
http://server62:8080/solr/COLLP_shard8_replica2/]
2018-09-19 23:45:20.832 INFO
(recoveryExecutor-3-thread-5-processing-n:server62:8080_solr
x:COLLP_shard8_replica2 s:shard8 c:COLLP r:core_node16) [c:COLLP s:shard8
r:core_node16 x:COLLP_shard8_replica2] o.a.s.c.RecoveryStrategy Sending
prep recovery command to [http://server61:8080/solr]; [WaitForState:
action=PREPRECOVERY&core=COLLP_shard8_replica1&nodeName=server62:8080_solr&coreNodeName=core_node16&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
2018-09-19 23:45:20.861 INFO (Thread-57618) [ ] o.a.s.u.SolrIndexConfig
IndexWriter infoStream solr logging is enabled
2018-09-19 23:45:20.863 INFO (Thread-57618) [ ] o.a.s.c.SolrConfig Using
Lucene MatchVersion: 6.6.2
2018-09-19 23:45:20.924 INFO (Thread-57618) [ ] o.a.s.s.IndexSchema
[COLLP_shard8_replica2] Schema name=COLLP
2018-09-19 23:45:20.931 INFO
(zkCallback-5-thread-89-processing-n:server62:8080_solr) [ ]
o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
state:SyncConnected type:NodeDataChanged
path:/collections/COLLP/state.json] for collection [COLLP] has occurred -
updating... (live nodes size: [16])
2018-09-19 23:45:21.075 INFO
(recoveryExecutor-3-thread-6-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Begin
buffering updates. core=[COLL_shard8_replica2]
2018-09-19 23:45:21.075 INFO
(recoveryExecutor-3-thread-6-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.u.UpdateLog Starting to buffer
updates. FSUpdateLog{state=ACTIVE,
tlog=tlog{file=/app/solr/data/COLL_shard8_replica2/data/tlog/tlog.0000000000000051065.1612081196978667520
refcount=1}}
2018-09-19 23:45:21.075 INFO
(recoveryExecutor-3-thread-6-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Publishing
state of core [COLL_shard8_replica2] as recovering, leader is [
http://server61:8080/solr/COLL_shard8_replica1/] and I am [
http://server62:8080/solr/COLL_shard8_replica2/]
2018-09-19 23:45:21.079 INFO
(recoveryExecutor-3-thread-6-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Sending prep
recovery command to [http://server61:8080/solr]; [WaitForState:
action=PREPRECOVERY&core=COLL_shard8_replica1&nodeName=server62:8080_solr&coreNodeName=core_node16&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
2018-09-19 23:45:21.084 INFO
(searcherExecutor-7-thread-1-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.QuerySenderListener
QuerySenderListener sending requests to Searcher@711c5774[COLL_shard8_replica2]
main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_8j4y(6.6.2):C879512/181368:delGen=2714)
Uninverting(_8z2y(6.6.2):C801846/163505:delGen=4343)
Uninverting(_81f9(6.6.2):C774110/378113:delGen=2398)
Uninverting(_82ll(6.6.2):C769263/348530:delGen=2427)
Uninverting(_83ne(6.6.2):C848884/94597:delGen=2133)
Uninverting(_4l73(6.6.2):C814472/317397:delGen=2514)
Uninverting(_7yqo(6.6.2):C724552/169736:delGen=3155)
Uninverting(_852r(6.6.2):C707686/75054:delGen=3038)
Uninverting(_ejht(6.6.2):C725012/321262:delGen=3591)
Uninverting(_gxvh(6.6.2):c432789/82761:delGen=1078)
Uninverting(_gblg(6.6.2):c215311/113006:delGen=1782)
Uninverting(_h8mr(6.6.2):c92526/14080:delGen=277)
Uninverting(_h71f(6.6.2):c51823/8823:delGen=371)
Uninverting(_h1p2(6.6.2):c58771/20719:delGen=618)
Uninverting(_h8uz(6.6.2):c9264/2802:delGen=143)
Uninverting(_hb7e(6.6.2):c35846/429:delGen=27)
Uninverting(_h9m4(6.6.2):c12335/1407:delGen=114)
Uninverting(_haiz(6.6.2):c9691/1789:delGen=68)
Uninverting(_halr(6.6.2):c960/340:delGen=25)
Uninverting(_hb16(6.6.2):c1196/69:delGen=12)
Uninverting(_hb5q(6.6.2):c2112/867:delGen=7)
Uninverting(_hb6u(6.6.2):c648/65:delGen=8)
Uninverting(_hb74(6.6.2):c664/36:delGen=10)
Uninverting(_hbba(6.6.2):c465/72:delGen=3)
Uninverting(_hbd1(6.6.2):c1224/1:delGen=1)
Uninverting(_hba6(6.6.2):c504/31:delGen=6)
Uninverting(_hbcq(6.6.2):c377/1:delGen=1)
Uninverting(_hbe7(6.6.2):c2163/1:delGen=1)
Uninverting(_hbdx(6.6.2):c506/3:delGen=1)
Uninverting(_hbfl(6.6.2):c71/1:delGen=1)
Uninverting(_hbfb(6.6.2):c62/1:delGen=1)
Uninverting(_hbed(6.6.2):C206/3:delGen=1)
Uninverting(_hbfm(6.6.2):C6/2:delGen=1)
Uninverting(_hbfn(6.6.2):C560/281:delGen=2)
Uninverting(_hbfo(6.6.2):C12/7:delGen=1)
Uninverting(_hbfp(6.6.2):C4/2:delGen=1)
Uninverting(_hbfq(6.6.2):C4/2:delGen=1)
Uninverting(_hbfs(6.6.2):C9/5:delGen=1)))}
2018-09-19 23:45:21.084 INFO
(searcherExecutor-7-thread-1-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.QuerySenderListener
QuerySenderListener done.
2018-09-19 23:45:21.084 INFO
(searcherExecutor-7-thread-1-processing-n:server62:8080_solr
x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8
r:core_node16 x:COLL_shard8_replica2] o.a.s.c.SolrCore
[COLL_shard8_replica2] Registered new searcher
Searcher@711c5774[COLL_shard8_replica2]
main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_8j4y(6.6.2):C879512/181368:delGen=2714)
Uninverting(_8z2y(6.6.2):C801846/163505:delGen=4343)
Uninverting(_81f9(6.6.2):C774110/378113:delGen=2398)
Uninverting(_82ll(6.6.2):C769263/348530:delGen=2427)
Uninverting(_83ne(6.6.2):C848884/94597:delGen=2133)
Uninverting(_4l73(6.6.2):C814472/317397:delGen=2514)
Uninverting(_7yqo(6.6.2):C724552/169736:delGen=3155)
Uninverting(_852r(6.6.2):C707686/75054:delGen=3038)
Uninverting(_ejht(6.6.2):C725012/321262:delGen=3591)
Uninverting(_gxvh(6.6.2):c432789/82761:delGen=1078)
Uninverting(_gblg(6.6.2):c215311/113006:delGen=1782)
Uninverting(_h8mr(6.6.2):c92526/14080:delGen=277)
Uninverting(_h71f(6.6.2):c51823/8823:delGen=371)
Uninverting(_h1p2(6.6.2):c58771/20719:delGen=618)
Uninverting(_h8uz(6.6.2):c9264/2802:delGen=143)
Uninverting(_hb7e(6.6.2):c35846/429:delGen=27)
Uninverting(_h9m4(6.6.2):c12335/1407:delGen=114)
Uninverting(_haiz(6.6.2):c9691/1789:delGen=68)
Uninverting(_halr(6.6.2):c960/340:delGen=25)
Uninverting(_hb16(6.6.2):c1196/69:delGen=12)
Uninverting(_hb5q(6.6.2):c2112/867:delGen=7)
Uninverting(_hb6u(6.6.2):c648/65:delGen=8)
Uninverting(_hb74(6.6.2):c664/36:delGen=10)
Uninverting(_hbba(6.6.2):c465/72:delGen=3)
Uninverting(_hbd1(6.6.2):c1224/1:delGen=1)
Uninverting(_hba6(6.6.2):c504/31:delGen=6)
Uninverting(_hbcq(6.6.2):c377/1:delGen=1)
Uninverting(_hbe7(6.6.2):c2163/1:delGen=1)
Uninverting(_hbdx(6.6.2):c506/3:delGen=1)
Uninverting(_hbfl(6.6.2):c71/1:delGen=1)
Uninverting(_hbfb(6.6.2):c62/1:delGen=1)
Uninverting(_hbed(6.6.2):C206/3:delGen=1)
Uninverting(_hbfm(6.6.2):C6/2:delGen=1)
Uninverting(_hbfn(6.6.2):C560/281:delGen=2)
Uninverting(_hbfo(6.6.2):C12/7:delGen=1)
Uninverting(_hbfp(6.6.2):C4/2:delGen=1)
Uninverting(_hbfq(6.6.2):C4/2:delGen=1)
Uninverting(_hbfs(6.6.2):C9/5:delGen=1)))}
On Sat, Sep 22, 2018 at 2:20 AM Susheel Kumar <su...@gmail.com> wrote:
> Hello,
>
> I noticed one of the replica's in Recover Failed status and after trying
> to recreate the replica/restart the node to recover, I see below error from
> solr log. The leader for this shard8 replica2 i.e. replica1@server 61
> seems to be fine and serving the queries.
>
> What does this indicate "SolrIndexWriter was not closed prior to
> finalize(), indicates a bug -- POSSIBLE RESOURCE LEAK!!!" from below log.
>
> 2018-09-22 06:00:13.686 ERROR (Finalizer) [ ] o.a.s.u.SolrIndexWriter Error closing IndexWriter2018-09-22 05:58:13.409 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=5
> 2018-09-22 05:58:13.686 INFO (qtp834133664-19) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=39
> 2018-09-22 05:58:19.338 ERROR (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.ReplicationHandler Index fetch failed :org.apache.solr.common.SolrException: Index fetch failed :
> at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:598)
> at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:301)
> at org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:400)
> at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:219)
> at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:471)
> at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:284)
> at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
> 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:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> Caused by: org.apache.lucene.index.CorruptIndexException: codec header mismatch: actual header=1997958933 vs expected header=1071082519 (resource=BufferedChecksumIndexInput(MMapIndexInput(path="/app/solr/data/COLL_shard8_replica2/data/index/_8ktm.fnm")))
> at org.apache.lucene.codecs.CodecUtil.checkHeader(CodecUtil.java:196)
> at org.apache.lucene.codecs.CodecUtil.checkIndexHeader(CodecUtil.java:255)
> at org.apache.lucene.codecs.lucene60.Lucene60FieldInfosFormat.read(Lucene60FieldInfosFormat.java:117)
> at org.apache.lucene.index.IndexWriter.readFieldInfos(IndexWriter.java:1063)
> at org.apache.lucene.index.IndexWriter.getFieldNumberMap(IndexWriter.java:1075)
> at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:960)
> at org.apache.solr.update.SolrIndexWriter.<init>(SolrIndexWriter.java:118)
> at org.apache.solr.update.SolrIndexWriter.create(SolrIndexWriter.java:93)
> at org.apache.solr.update.DefaultSolrCoreState.createMainIndexWriter(DefaultSolrCoreState.java:257)
> at org.apache.solr.update.DefaultSolrCoreState.changeWriter(DefaultSolrCoreState.java:220)
> at org.apache.solr.update.DefaultSolrCoreState.openIndexWriter(DefaultSolrCoreState.java:245)
> at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:551)
> ... 12 more
> Suppressed: org.apache.lucene.index.CorruptIndexException: checksum failed (hardware problem?) : expected=e42fdf3e actual=c0432e62 (resource=BufferedChecksumIndexInput(MMapIndexInput(path="/app/solr/data/COLL_shard8_replica2/data/index/_8ktm.fnm")))
> at org.apache.lucene.codecs.CodecUtil.checkFooter(CodecUtil.java:419)
> at org.apache.lucene.codecs.CodecUtil.checkFooter(CodecUtil.java:462)
> at org.apache.lucene.codecs.lucene60.Lucene60FieldInfosFormat.read(Lucene60FieldInfosFormat.java:171)
> ... 21 more
>
> 2018-09-22 05:58:19.338 ERROR (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Error while trying to recover:org.apache.solr.common.SolrException: Replication for recovery failed.
> at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:222)
> at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:471)
> at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:284)
> at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
> 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:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
>
> 2018-09-22 05:58:19.338 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Replay not started, or was not successful... still buffering updates.
> 2018-09-22 05:58:19.338 ERROR (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Recovery failed - trying again... (0)
> 2018-09-22 05:58:19.338 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Wait [2.0] seconds before trying to recover again (attempt=1)
> 2018-09-22 05:58:23.352 INFO (qtp834133664-20) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=0
> 2018-09-22 05:58:23.486 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=18
> 2018-09-22 05:58:23.763 INFO (qtp834133664-22) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=53
> 2018-09-22 05:58:29.339 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[COLL_shard8_replica2]
> 2018-09-22 05:58:29.339 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.u.UpdateLog Restarting buffering. previous=RecoveryInfo{adds=0 deletes=0 deleteByQuery=0 errors=0 positionOfStart=0}
> 2018-09-22 05:58:29.339 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state=BUFFERING, tlog=tlog{file=/app/solr/data/COLL_shard8_replica2/data/tlog/tlog.0000000000000000000.1612285920588857344 refcount=2}}
> 2018-09-22 05:58:29.339 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Publishing state of core [COLL_shard8_replica2] as recovering, leader is [http://server61:8080/solr/COLL_shard8_replica1/] and I am [http://server62:8080/solr/COLL_shard8_replica2/]
> 2018-09-22 05:58:29.343 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://server61:8080/solr]; [WaitForState: action=PREPRECOVERY&core=COLL_shard8_replica1&nodeName=server62:8080_solr&coreNodeName=core_node16&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
> 2018-09-22 05:58:29.351 INFO (zkCallback-5-thread-23-processing-n:server62:8080_solr) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/COLL/state.json] for collection [COLL] has occurred - updating... (live nodes size: [16])
> 2018-09-22 05:58:31.846 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Starting Replication Recovery.
> 2018-09-22 05:58:31.846 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Attempting to replicate from [http://server61:8080/solr/COLL_shard8_replica1/].
> 2018-09-22 05:58:32.234 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Master's generation: 51970
> 2018-09-22 05:58:32.234 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Master's version: 1537595911854
> 2018-09-22 05:58:32.234 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Slave's generation: 1
> 2018-09-22 05:58:32.234 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Slave's version: 0
> 2018-09-22 05:58:32.234 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Starting replication process
> 2018-09-22 05:58:32.290 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Number of files in latest index in master: 257
> 2018-09-22 05:58:32.309 ERROR (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.ReplicationHandler Index fetch failed :org.apache.solr.common.SolrException: Index fetch failed :
> at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:598)
> at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:301)
> at org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:400)
> at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:219)
> at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:471)
> at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:284)
> at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
> 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:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> Caused by: org.apache.lucene.index.CorruptIndexException: codec header mismatch: actual header=1997958933 vs expected header=1071082519 (resource=BufferedChecksumIndexInput(MMapIndexInput(path="/app/solr/data/COLL_shard8_replica2/data/index/_8ktm.fnm")))
> at org.apache.lucene.codecs.CodecUtil.checkHeader(CodecUtil.java:196)
> at org.apache.lucene.codecs.CodecUtil.checkIndexHeader(CodecUtil.java:255)
> at org.apache.lucene.codecs.lucene60.Lucene60FieldInfosFormat.read(Lucene60FieldInfosFormat.java:117)
> at org.apache.lucene.index.IndexWriter.readFieldInfos(IndexWriter.java:1063)
> at org.apache.lucene.index.IndexWriter.getFieldNumberMap(IndexWriter.java:1075)
> at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:960)
> at org.apache.solr.update.SolrIndexWriter.<init>(SolrIndexWriter.java:118)
> at org.apache.solr.update.SolrIndexWriter.create(SolrIndexWriter.java:93)
> at org.apache.solr.update.DefaultSolrCoreState.createMainIndexWriter(DefaultSolrCoreState.java:257)
> at org.apache.solr.update.DefaultSolrCoreState.changeWriter(DefaultSolrCoreState.java:220)
> at org.apache.solr.update.DefaultSolrCoreState.newIndexWriter(DefaultSolrCoreState.java:229)
> at org.apache.solr.update.DirectUpdateHandler2.newIndexWriter(DirectUpdateHandler2.java:726)
> at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:457)
> ... 12 more
> Suppressed: org.apache.lucene.index.CorruptIndexException: checksum failed (hardware problem?) : expected=e42fdf3e actual=c0432e62 (resource=BufferedChecksumIndexInput(MMapIndexInput(path="/app/solr/data/COLL_shard8_replica2/data/index/_8ktm.fnm")))
> at org.apache.lucene.codecs.CodecUtil.checkFooter(CodecUtil.java:419)
> at org.apache.lucene.codecs.CodecUtil.checkFooter(CodecUtil.java:462)
> at org.apache.lucene.codecs.lucene60.Lucene60FieldInfosFormat.read(Lucene60FieldInfosFormat.java:171)
> ... 22 more
>
> 2018-09-22 05:58:32.309 ERROR (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Error while trying to recover:org.apache.solr.common.SolrException: Replication for recovery failed.
> at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:222)
> at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:471)
> at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:284)
> at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
> 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:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
>
> 2018-09-22 05:58:32.310 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Replay not started, or was not successful... still buffering updates.
> 2018-09-22 05:58:32.310 ERROR (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Recovery failed - trying again... (1)
> 2018-09-22 05:58:32.310 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Wait [4.0] seconds before trying to recover again (attempt=2)
> 2018-09-22 05:58:33.423 INFO (qtp834133664-15) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=4
> 2018-09-22 05:58:33.548 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=3
> 2018-09-22 05:58:33.834 INFO (qtp834133664-19) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=44
> 2018-09-22 05:58:43.480 INFO (qtp834133664-13) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=2
> 2018-09-22 05:58:43.624 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=8
> 2018-09-22 05:58:43.882 INFO (qtp834133664-22) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=23
> 2018-09-22 05:58:52.310 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[COLL_shard8_replica2]
> 2018-09-22 05:58:52.310 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.u.UpdateLog Restarting buffering. previous=RecoveryInfo{adds=0 deletes=0 deleteByQuery=0 errors=0 positionOfStart=2630296}
> 2018-09-22 05:58:52.310 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state=BUFFERING, tlog=tlog{file=/app/solr/data/COLL_shard8_replica2/data/tlog/tlog.0000000000000000000.1612285920588857344 refcount=2}}
> 2018-09-22 05:58:52.310 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Publishing state of core [COLL_shard8_replica2] as recovering, leader is [http://server61:8080/solr/COLL_shard8_replica1/] and I am [http://server62:8080/solr/COLL_shard8_replica2/]
> 2018-09-22 05:58:52.317 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://server61:8080/solr]; [WaitForState: action=PREPRECOVERY&core=COLL_shard8_replica1&nodeName=server62:8080_solr&coreNodeName=core_node16&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
> 2018-09-22 05:58:52.325 INFO (zkCallback-5-thread-23-processing-n:server62:8080_solr) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/COLL/state.json] for collection [COLL] has occurred - updating... (live nodes size: [16])
> 2018-09-22 05:58:53.538 INFO (qtp834133664-20) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=8
> 2018-09-22 05:58:53.679 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=4
> 2018-09-22 05:58:53.983 INFO (qtp834133664-19) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=63
> 2018-09-22 05:58:54.820 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Starting Replication Recovery.
> 2018-09-22 05:58:54.820 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.RecoveryStrategy Attempting to replicate from [http://server61:8080/solr/COLL_shard8_replica1/].
> 2018-09-22 05:58:54.967 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Master's generation: 51971
> 2018-09-22 05:58:54.967 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Master's version: 1537595934827
> 2018-09-22 05:58:54.967 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Slave's generation: 1
> 2018-09-22 05:58:54.967 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Slave's version: 0
> 2018-09-22 05:58:54.967 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Starting replication process
> 2018-09-22 05:58:55.018 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Number of files in latest index in master: 173
> 2018-09-22 05:58:55.019 INFO (recoveryExecutor-3-thread-3-processing-n:server62:8080_solr x:COLL_shard8_replica2 s:shard8 c:COLL r:core_node16) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.h.IndexFetcher Starting download (fullCopy=true) to NRTCachingDirectory(MMapDirectory@/app/solr/data/COLL_shard8_replica2/data/index.20180922055855018 lockFactory=org.apache.lucene.store.NativeFSLockFactory@74255cc4; maxCacheMB=48.0 maxMergeSizeMB=4.0)
> 2018-09-22 05:59:03.590 INFO (qtp834133664-15) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=0
> 2018-09-22 05:59:03.781 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=25
> 2018-09-22 05:59:04.061 INFO (qtp834133664-22) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=52
> 2018-09-22 05:59:13.125 INFO (qtp834133664-13) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=42
> 2018-09-22 05:59:13.672 INFO (qtp834133664-20) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=2
> 2018-09-22 05:59:13.812 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=9
> 2018-09-22 05:59:23.229 INFO (qtp834133664-19) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=43
> 2018-09-22 05:59:23.275 INFO (qtp834133664-15) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=18
> 2018-09-22 05:59:23.732 INFO (qtp834133664-20) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=3
> 2018-09-22 05:59:23.915 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=18
> 2018-09-22 05:59:33.390 INFO (qtp834133664-22) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=89
> 2018-09-22 05:59:33.778 INFO (qtp834133664-20) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=0
> 2018-09-22 05:59:33.958 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=19
> 2018-09-22 05:59:43.461 INFO (qtp834133664-13) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=46
> 2018-09-22 05:59:43.862 INFO (qtp834133664-20) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=2
> 2018-09-22 05:59:44.009 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=15
> 2018-09-22 05:59:53.515 INFO (qtp834133664-19) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=24
> 2018-09-22 05:59:53.915 INFO (qtp834133664-20) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=4
> 2018-09-22 05:59:54.075 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=15
> 2018-09-22 06:00:03.177 INFO (qtp834133664-15) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=21
> 2018-09-22 06:00:03.596 INFO (qtp834133664-22) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=51
> 2018-09-22 06:00:03.977 INFO (qtp834133664-20) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=12
> 2018-09-22 06:00:13.207 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=4
> 2018-09-22 06:00:13.685 INFO (qtp834133664-13) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=65
> 2018-09-22 06:00:13.686 ERROR (Finalizer) [ ] o.a.s.u.SolrIndexWriter SolrIndexWriter was not closed prior to finalize(), indicates a bug -- POSSIBLE RESOURCE LEAK!!!
> 2018-09-22 06:00:13.686 ERROR (Finalizer) [ ] o.a.s.u.SolrIndexWriter Error closing IndexWriter
> java.lang.NullPointerException
> at org.apache.lucene.index.IndexWriter.doFlush(IndexWriter.java:3414)
> at org.apache.lucene.index.IndexWriter.flush(IndexWriter.java:3376)
> at org.apache.lucene.index.IndexWriter.shutdown(IndexWriter.java:1126)
> at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1171)
> at org.apache.solr.update.SolrIndexWriter.close(SolrIndexWriter.java:278)
> at org.apache.solr.update.SolrIndexWriter.finalize(SolrIndexWriter.java:334)
> at java.lang.System$2.invokeFinalize(System.java:1270)
> at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:98)
> at java.lang.ref.Finalizer.access$100(Finalizer.java:34)
> at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:210)
> 2018-09-22 06:00:13.686 ERROR (Finalizer) [ ] o.a.s.u.SolrIndexWriter SolrIndexWriter was not closed prior to finalize(), indicates a bug -- POSSIBLE RESOURCE LEAK!!!
> 2018-09-22 06:00:13.687 ERROR (Finalizer) [ ] o.a.s.u.SolrIndexWriter Error closing IndexWriter
> java.lang.NullPointerException
> at org.apache.lucene.index.IndexWriter.doFlush(IndexWriter.java:3414)
> at org.apache.lucene.index.IndexWriter.flush(IndexWriter.java:3376)
> at org.apache.lucene.index.IndexWriter.shutdown(IndexWriter.java:1126)
> at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1171)
> at org.apache.solr.update.SolrIndexWriter.close(SolrIndexWriter.java:278)
> at org.apache.solr.update.SolrIndexWriter.finalize(SolrIndexWriter.java:334)
> at java.lang.System$2.invokeFinalize(System.java:1270)
> at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:98)
> at java.lang.ref.Finalizer.access$100(Finalizer.java:34)
> at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:210)
> 2018-09-22 06:00:14.018 INFO (qtp834133664-20) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=7
> 2018-09-22 06:00:23.270 INFO (qtp834133664-15) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=15
> 2018-09-22 06:00:23.775 INFO (qtp834133664-19) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=42
> 2018-09-22 06:00:24.058 INFO (qtp834133664-20) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=0
> 2018-09-22 06:00:33.139 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=19
> 2018-09-22 06:00:33.345 INFO (qtp834133664-15) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=24
> 2018-09-22 06:00:33.844 INFO (qtp834133664-22) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=43
> 2018-09-22 06:00:43.165 INFO (qtp834133664-20) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=0
> 2018-09-22 06:00:43.398 INFO (qtp834133664-15) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=8
> 2018-09-22 06:00:43.915 INFO (qtp834133664-13) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=46
> 2018-09-22 06:00:53.211 INFO (qtp834133664-21) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=2
> 2018-09-22 06:00:53.448 INFO (qtp834133664-15) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=0
> 2018-09-22 06:00:53.987 INFO (qtp834133664-19) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=49
> 2018-09-22 06:01:03.252 INFO (qtp834133664-20) [c:COLL s:shard8 r:core_node16 x:COLL_shard8_replica2] o.a.s.c.S.Request [COLL_shard8_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&update.chain=cdcr-processor-chain&distrib.from=http://server61:8080/solr/COLL_shard8_replica1/&wt=javabin&version=2} status=0 QTime=0
>
>
>
>