You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2018/08/10 22:07:29 UTC
[JENKINS] Lucene-Solr-repro - Build # 1191 - Unstable
Build: https://builds.apache.org/job/Lucene-Solr-repro/1191/
[...truncated 28 lines...]
[repro] Jenkins log URL: https://builds.apache.org/job/Lucene-Solr-BadApples-NightlyTests-master/23/consoleText
[repro] Revision: 9c02bf09b765197cc1360baa831b55f511059f42
[repro] Ant options: -Dtests.multiplier=2 -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt
[repro] Repro line: ant test -Dtestcase=TestLatLonLineShapeQueries -Dtests.method=testRandomBig -Dtests.seed=BE6FBD2BC96F66EA -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=en-SG -Dtests.timezone=America/Campo_Grande -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[repro] Repro line: ant test -Dtestcase=HdfsChaosMonkeyNothingIsSafeTest -Dtests.method=test -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=es-CL -Dtests.timezone=Pacific/Palau -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[repro] Repro line: ant test -Dtestcase=HdfsChaosMonkeyNothingIsSafeTest -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=es-CL -Dtests.timezone=Pacific/Palau -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[repro] Repro line: ant test -Dtestcase=HdfsRestartWhileUpdatingTest -Dtests.method=test -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=lt -Dtests.timezone=Africa/Porto-Novo -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[repro] Repro line: ant test -Dtestcase=HdfsRestartWhileUpdatingTest -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=lt -Dtests.timezone=Africa/Porto-Novo -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testBatchAddsWithDelete -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=pl-PL -Dtests.timezone=America/St_Thomas -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testBufferOnNonLeader -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=pl-PL -Dtests.timezone=America/St_Thomas -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testOps -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=pl-PL -Dtests.timezone=America/St_Thomas -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testReplicationAfterLeaderChange -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=pl-PL -Dtests.timezone=America/St_Thomas -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testBatchBoundaries -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=pl-PL -Dtests.timezone=America/St_Thomas -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testReplicationStartStop -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=pl-PL -Dtests.timezone=America/St_Thomas -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testReplicationAfterRestart -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=pl-PL -Dtests.timezone=America/St_Thomas -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testResilienceWithDeleteByQueryOnTarget -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=pl-PL -Dtests.timezone=America/St_Thomas -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[repro] Repro line: ant test -Dtestcase=CdcrReplicationDistributedZkTest -Dtests.method=testUpdateLogSynchronisation -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=pl-PL -Dtests.timezone=America/St_Thomas -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[repro] git rev-parse --abbrev-ref HEAD
[repro] git rev-parse HEAD
[repro] Initial local git branch/revision: cdc0959afcc3d64cbc0f42951964979680b080a0
[repro] git fetch
[repro] git checkout 9c02bf09b765197cc1360baa831b55f511059f42
[...truncated 2 lines...]
[repro] git merge --ff-only
[...truncated 1 lines...]
[repro] ant clean
[...truncated 6 lines...]
[repro] Test suites by module:
[repro] lucene/sandbox
[repro] TestLatLonLineShapeQueries
[repro] solr/core
[repro] HdfsRestartWhileUpdatingTest
[repro] CdcrReplicationDistributedZkTest
[repro] HdfsChaosMonkeyNothingIsSafeTest
[repro] ant compile-test
[...truncated 175 lines...]
[repro] ant test-nocompile -Dtests.dups=5 -Dtests.maxfailures=5 -Dtests.class="*.TestLatLonLineShapeQueries" -Dtests.showOutput=onerror -Dtests.multiplier=2 -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.seed=BE6FBD2BC96F66EA -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=en-SG -Dtests.timezone=America/Campo_Grande -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[...truncated 392 lines...]
[repro] Setting last failure code to 256
[repro] ant compile-test
[...truncated 3244 lines...]
[repro] ant test-nocompile -Dtests.dups=5 -Dtests.maxfailures=15 -Dtests.class="*.HdfsRestartWhileUpdatingTest|*.CdcrReplicationDistributedZkTest|*.HdfsChaosMonkeyNothingIsSafeTest" -Dtests.showOutput=onerror -Dtests.multiplier=2 -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=lt -Dtests.timezone=Africa/Porto-Novo -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[...truncated 152183 lines...]
[junit4] 2> 2036108 ERROR (Finalizer) [ ] o.a.s.c.SolrCore REFCOUNT ERROR: unreferenced org.apache.solr.core.SolrCore@204a2817 (collection1_shard1_replica_n25) has a reference count of -1
[junit4] 2> 2036108 ERROR (Finalizer) [ ] o.a.s.c.SolrCore REFCOUNT ERROR: unreferenced org.apache.solr.core.SolrCore@1358121e (collection1_shard1_replica_n23) has a reference count of -1
[junit4] 2> 2036108 ERROR (Finalizer) [ ] o.a.s.c.SolrCore REFCOUNT ERROR: unreferenced org.apache.solr.core.SolrCore@7b44f0b9 (collection1_shard1_replica_n21) has a reference count of -1
[junit4] 2> 2036108 ERROR (Finalizer) [ ] o.a.s.c.SolrCore REFCOUNT ERROR: unreferenced org.apache.solr.core.SolrCore@5de276bc (collection1_shard1_replica_n25) has a reference count of -1
[junit4] 2> 2036109 ERROR (Finalizer) [ ] o.a.s.c.SolrCore REFCOUNT ERROR: unreferenced org.apache.solr.core.SolrCore@1cb6f5ee (collection1_shard1_replica_n23) has a reference count of -1
[junit4] 2> 2036109 ERROR (Finalizer) [ ] o.a.s.c.SolrCore REFCOUNT ERROR: unreferenced org.apache.solr.core.SolrCore@223172da (collection1_shard1_replica_n21) has a reference count of -1
[junit4] 2> 2036109 ERROR (Finalizer) [ ] o.a.s.c.SolrCore REFCOUNT ERROR: unreferenced org.apache.solr.core.SolrCore@16db113c (control_collection_shard1_replica_n1) has a reference count of -1
[junit4] 2> 2036173 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id
[junit4] 2> 2036195 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.CoreContainer Creating SolrCore 'collection1_shard3_replica_t99' using configuration from collection collection1, trusted=true
[junit4] 2> 2036196 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.collection1.shard3.replica_t99' (registry 'solr.core.collection1.shard3.replica_t99') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@15e8e80f
[junit4] 2> 2036196 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.HdfsDirectoryFactory solr.hdfs.home=hdfs://lucene2-us-west.apache.org:34266/solr_hdfs_home
[junit4] 2> 2036196 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.HdfsDirectoryFactory Solr Kerberos Authentication disabled
[junit4] 2> 2036196 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 2036196 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.SolrCore [[collection1_shard3_replica_t99] ] Opening new SolrCore at [/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsChaosMonkeyNothingIsSafeTest_F3CDB154F464C6A0-001/shard-10-001/cores/collection1_shard3_replica_t99], dataDir=[hdfs://lucene2-us-west.apache.org:34266/solr_hdfs_home/collection1/core_node100/data/]
[junit4] 2> 2036198 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://lucene2-us-west.apache.org:34266/solr_hdfs_home/collection1/core_node100/data/snapshot_metadata
[junit4] 2> 2036221 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
[junit4] 2> 2036221 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [8388608] will allocate [1] slabs and use ~[8388608] bytes
[junit4] 2> 2036233 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.s.b.BlockDirectory Block cache on write is disabled
[junit4] 2> 2036234 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://lucene2-us-west.apache.org:34266/solr_hdfs_home/collection1/core_node100/data
[junit4] 2> 2036292 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://lucene2-us-west.apache.org:34266/solr_hdfs_home/collection1/core_node100/data/index
[junit4] 2> 2036306 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
[junit4] 2> 2036306 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [8388608] will allocate [1] slabs and use ~[8388608] bytes
[junit4] 2> 2036321 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.s.b.BlockDirectory Block cache on write is disabled
[junit4] 2> 2036322 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=32, maxMergeAtOnceExplicit=11, maxMergedSegmentMB=40.470703125, floorSegmentMB=0.3681640625, forceMergeDeletesPctAllowed=7.159042072915542, segmentsPerTier=46.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.204218408112585, deletesPctAllowed=33.772894637341295
[junit4] 2> 2036327 INFO (qtp345789901-15454) [n:127.0.0.1:35563__evt%2Fzi c:collection1 s:shard1 r:core_node88 x:collection1_shard1_replica_t87] o.a.s.c.S.Request [collection1_shard1_replica_t87] webapp=/_evt/zi path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 2036335 INFO (indexFetcher-3062-thread-1) [ ] o.a.s.h.IndexFetcher Master's generation: 1
[junit4] 2> 2036335 INFO (indexFetcher-3062-thread-1) [ ] o.a.s.h.IndexFetcher Master's version: 0
[junit4] 2> 2036336 INFO (indexFetcher-3062-thread-1) [ ] o.a.s.h.IndexFetcher Slave's generation: 1
[junit4] 2> 2036336 INFO (indexFetcher-3062-thread-1) [ ] o.a.s.h.IndexFetcher Slave's version: 0
[junit4] 2> 2036336 INFO (indexFetcher-3062-thread-1) [ ] o.a.s.h.IndexFetcher New index in Master. Deleting mine...
[junit4] 2> 2036336 INFO (indexFetcher-3062-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@139c242e[collection1_shard1_replica_t95] main]
[junit4] 2> 2036338 INFO (searcherExecutor-3047-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard1_replica_t95] Registered new searcher Searcher@139c242e[collection1_shard1_replica_t95] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2036409 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:33970 is added to blk_1073741835_1011{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-31b97e9a-b5a8-4c91-9c64-4305897c7e11:NORMAL:127.0.0.1:41416|RBW], ReplicaUC[[DISK]DS-708d0b63-3f3a-4e95-9e48-39921ca5284b:NORMAL:127.0.0.1:33970|RBW]]} size 0
[junit4] 2> 2036409 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:41416 is added to blk_1073741835_1011{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-31b97e9a-b5a8-4c91-9c64-4305897c7e11:NORMAL:127.0.0.1:41416|RBW], ReplicaUC[[DISK]DS-708d0b63-3f3a-4e95-9e48-39921ca5284b:NORMAL:127.0.0.1:33970|RBW]]} size 0
[junit4] 2> 2036455 WARN (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,attributes = {initParams=a, name=/dump, class=DumpRequestHandler},args = {defaults={a=A,b=B}}}
[junit4] 2> 2036595 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.HdfsUpdateLog
[junit4] 2> 2036596 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 2036596 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.u.HdfsUpdateLog Initializing HdfsUpdateLog: tlogDfsReplication=2
[junit4] 2> 2036616 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.u.CommitTracker Hard AutoCommit: if uncommited for 15000ms;
[junit4] 2> 2036617 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 2036619 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.MockRandomMergePolicy: org.apache.lucene.index.MockRandomMergePolicy@560b9576
[junit4] 2> 2036635 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.s.SolrIndexSearcher Opening [Searcher@a9d83d9[collection1_shard3_replica_t99] main]
[junit4] 2> 2036636 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 2036637 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 2036637 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 2036654 INFO (searcherExecutor-3079-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.SolrCore [collection1_shard3_replica_t99] Registered new searcher Searcher@a9d83d9[collection1_shard3_replica_t99] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2036654 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1608450653728800768
[junit4] 2> 2036659 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.ZkShardTerms Successful update of terms at /collections/collection1/terms/shard3 to Terms{values={core_node100=0, core_node92=0, core_node84=0}, version=4}
[junit4] 2> 2036660 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.c.ZkController Core needs to recover:collection1_shard3_replica_t99
[junit4] 2> 2036669 INFO (updateExecutor-4540-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.u.DefaultSolrCoreState Running recovery
[junit4] 2> 2036669 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.RecoveryStrategy Starting recovery process. recoveringAfterStartup=true
[junit4] 2> 2036691 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.RecoveryStrategy ###### startupVersions=[[]]
[junit4] 2> 2036691 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.ZkController collection1_shard3_replica_t99 stopping background replication from leader
[junit4] 2> 2036692 INFO (qtp482122760-15313) [n:127.0.0.1:36895__evt%2Fzi c:collection1 s:shard2 r:core_node82 x:collection1_shard2_replica_t81] o.a.s.c.S.Request [collection1_shard2_replica_t81] webapp=/_evt/zi path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 2036692 INFO (indexFetcher-3014-thread-1) [ ] o.a.s.h.IndexFetcher Master's generation: 1
[junit4] 2> 2036692 INFO (indexFetcher-3014-thread-1) [ ] o.a.s.h.IndexFetcher Master's version: 0
[junit4] 2> 2036692 INFO (indexFetcher-3014-thread-1) [ ] o.a.s.h.IndexFetcher Slave's generation: 1
[junit4] 2> 2036692 INFO (indexFetcher-3014-thread-1) [ ] o.a.s.h.IndexFetcher Slave's version: 0
[junit4] 2> 2036692 INFO (indexFetcher-3014-thread-1) [ ] o.a.s.h.IndexFetcher New index in Master. Deleting mine...
[junit4] 2> 2036693 INFO (indexFetcher-3014-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@4ca570b5[collection1_shard2_replica_t89] main]
[junit4] 2> 2036695 INFO (searcherExecutor-2999-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard2_replica_t89] Registered new searcher Searcher@4ca570b5[collection1_shard2_replica_t89] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2036695 INFO (qtp2057734636-15357) [n:127.0.0.1:39411__evt%2Fzi c:collection1 s:shard3 r:core_node84 x:collection1_shard3_replica_t83] o.a.s.c.S.Request [collection1_shard3_replica_t83] webapp=/_evt/zi path=/admin/ping params={wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 2036695 INFO (qtp2057734636-15357) [n:127.0.0.1:39411__evt%2Fzi c:collection1 s:shard3 r:core_node84 x:collection1_shard3_replica_t83] o.a.s.c.S.Request [collection1_shard3_replica_t83] webapp=/_evt/zi path=/admin/ping params={wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 2036696 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[collection1_shard3_replica_t99]
[junit4] 2> 2036719 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.u.UpdateLog Starting to buffer updates. HDFSUpdateLog{state=ACTIVE, tlog=null}
[junit4] 2> 2036719 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.RecoveryStrategy Publishing state of core [collection1_shard3_replica_t99] as recovering, leader is [http://127.0.0.1:39411/_evt/zi/collection1_shard3_replica_t83/] and I am [http://127.0.0.1:39820/_evt/zi/collection1_shard3_replica_t99/]
[junit4] 2> 2036720 INFO (qtp1413810141-15752) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 x:collection1_shard3_replica_t99] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&name=collection1_shard3_replica_t99&action=CREATE&collection=collection1&shard=shard3&wt=javabin&version=2&replicaType=TLOG} status=0 QTime=3874
[junit4] 2> 2036721 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.ZkShardTerms Successful update of terms at /collections/collection1/terms/shard3 to Terms{values={core_node100=0, core_node92=0, core_node100_recovering=0, core_node84=0}, version=5}
[junit4] 2> 2036723 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://127.0.0.1:39411/_evt/zi]; [WaitForState: action=PREPRECOVERY&core=collection1_shard3_replica_t83&nodeName=127.0.0.1:39820__evt%252Fzi&coreNodeName=core_node100&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
[junit4] 2> 2036724 INFO (qtp599385621-15696) [n:127.0.0.1:35891__evt%2Fzi c:collection1 ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={node=127.0.0.1:39820__evt%252Fzi&action=ADDREPLICA&collection=collection1&shard=shard3&type=TLOG&wt=javabin&version=2} status=0 QTime=3886
[junit4] 2> 2036738 INFO (qtp2057734636-15364) [n:127.0.0.1:39411__evt%2Fzi x:collection1_shard3_replica_t83] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node100, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true, maxTime: 183 s
[junit4] 2> 2036747 INFO (qtp2057734636-15364) [n:127.0.0.1:39411__evt%2Fzi x:collection1_shard3_replica_t83] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=collection1, shard=shard3, thisCore=collection1_shard3_replica_t83, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=recovering, localState=active, nodeName=127.0.0.1:39820__evt%2Fzi, coreNodeName=core_node100, onlyIfActiveCheckResult=false, nodeProps: core_node100:{"dataDir":"hdfs://lucene2-us-west.apache.org:34266/solr_hdfs_home/collection1/core_node100/data/","base_url":"http://127.0.0.1:39820/_evt/zi","node_name":"127.0.0.1:39820__evt%2Fzi","type":"TLOG","ulogDir":"hdfs://lucene2-us-west.apache.org:34266/solr_hdfs_home/collection1/core_node100/data/tlog","core":"collection1_shard3_replica_t99","shared_storage":"true","state":"recovering"}
[junit4] 2> 2036747 INFO (qtp2057734636-15364) [n:127.0.0.1:39411__evt%2Fzi x:collection1_shard3_replica_t83] o.a.s.h.a.PrepRecoveryOp Waited coreNodeName: core_node100, state: recovering, checkLive: true, onlyIfLeader: true for: 0 seconds.
[junit4] 2> 2036747 INFO (qtp2057734636-15364) [n:127.0.0.1:39411__evt%2Fzi x:collection1_shard3_replica_t83] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={nodeName=127.0.0.1:39820__evt%252Fzi&onlyIfLeaderActive=true&core=collection1_shard3_replica_t83&coreNodeName=core_node100&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=0 QTime=9
[junit4] 2> 2037013 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 11 in directory /home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsChaosMonkeyNothingIsSafeTest_F3CDB154F464C6A0-001/shard-11-001 of type TLOG
[junit4] 2> 2037014 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.e.j.s.Server jetty-9.4.11.v20180605; built: 2018-06-05T18:24:03.829Z; git: d5fc0523cfa96bfebfbda19606cad384d772f04c; jvm 1.8.0_172-b11
[junit4] 2> 2037015 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 2037016 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 2037016 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.e.j.s.session node0 Scavenging every 660000ms
[junit4] 2> 2037016 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@2765e403{/_evt/zi,null,AVAILABLE}
[junit4] 2> 2037016 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@43242f8d{HTTP/1.1,[http/1.1]}{127.0.0.1:44632}
[junit4] 2> 2037016 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.e.j.s.Server Started @2037081ms
[junit4] 2> 2037034 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=hdfs://lucene2-us-west.apache.org:34266/hdfs__lucene2-us-west.apache.org_34266__home_jenkins_jenkins-slave_workspace_Lucene-Solr-repro_solr_build_solr-core_test_J1_temp_solr.cloud.hdfs.HdfsChaosMonkeyNothingIsSafeTest_F3CDB154F464C6A0-001_tempDir-002_jetty11, replicaType=TLOG, solrconfig=solrconfig.xml, hostContext=/_evt/zi, hostPort=44632, coreRootDirectory=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/../../../../../../../../../../home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsChaosMonkeyNothingIsSafeTest_F3CDB154F464C6A0-001/shard-11-001/cores}
[junit4] 2> 2037034 ERROR (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 2037034 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
[junit4] 2> 2037034 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 8.0.0
[junit4] 2> 2037034 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 2037034 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 2037034 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-08-10T21:54:38.048Z
[junit4] 2> 2037036 INFO (zkConnectionManagerCallback-4556-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 2037037 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 2037037 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsChaosMonkeyNothingIsSafeTest_F3CDB154F464C6A0-001/shard-11-001/solr.xml
[junit4] 2> 2037041 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored
[junit4] 2> 2037041 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored
[junit4] 2> 2037042 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@15e8e80f, but no JMX reporters were configured - adding default JMX reporter.
[junit4] 2> 2037248 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.RecoveryStrategy Starting Replication Recovery.
[junit4] 2> 2037248 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.RecoveryStrategy Attempting to replicate from [http://127.0.0.1:39411/_evt/zi/collection1_shard3_replica_t83/].
[junit4] 2> 2037250 INFO (qtp2057734636-15360) [n:127.0.0.1:39411__evt%2Fzi c:collection1 s:shard3 r:core_node84 x:collection1_shard3_replica_t83] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1608450654353752064,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 2037250 INFO (qtp2057734636-15360) [n:127.0.0.1:39411__evt%2Fzi c:collection1 s:shard3 r:core_node84 x:collection1_shard3_replica_t83] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 2037267 INFO (qtp2057734636-15360) [n:127.0.0.1:39411__evt%2Fzi c:collection1 s:shard3 r:core_node84 x:collection1_shard3_replica_t83] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 2037267 INFO (qtp2057734636-15360) [n:127.0.0.1:39411__evt%2Fzi c:collection1 s:shard3 r:core_node84 x:collection1_shard3_replica_t83] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard3_replica_t83] webapp=/_evt/zi path=/update params={waitSearcher=true&openSearcher=false&commit=true&softCommit=false&commit_end_point=true&wt=javabin&version=2}{commit=} 0 17
[junit4] 2> 2037268 INFO (qtp2057734636-15357) [n:127.0.0.1:39411__evt%2Fzi c:collection1 s:shard3 r:core_node84 x:collection1_shard3_replica_t83] o.a.s.c.S.Request [collection1_shard3_replica_t83] webapp=/_evt/zi path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 2037278 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.h.IndexFetcher Master's generation: 1
[junit4] 2> 2037278 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.h.IndexFetcher Master's version: 0
[junit4] 2> 2037278 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.h.IndexFetcher Slave's generation: 1
[junit4] 2> 2037278 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.h.IndexFetcher Slave's version: 0
[junit4] 2> 2037278 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.h.IndexFetcher New index in Master. Deleting mine...
[junit4] 2> 2037359 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.s.SolrIndexSearcher Opening [Searcher@2f4d4f57[collection1_shard3_replica_t99] main]
[junit4] 2> 2037371 INFO (searcherExecutor-3079-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.SolrCore [collection1_shard3_replica_t99] Registered new searcher Searcher@2f4d4f57[collection1_shard3_replica_t99] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2037401 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.RecoveryStrategy Replication Recovery was successful.
[junit4] 2> 2037401 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.RecoveryStrategy Registering as Active after recovery.
[junit4] 2> 2037401 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.ZkController collection1_shard3_replica_t99 starting background replication from leader
[junit4] 2> 2037401 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.ReplicateFromLeader Will start replication from leader with poll interval: 0:0:7
[junit4] 2> 2037402 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.h.ReplicationHandler Poll scheduled at an interval of 7000ms
[junit4] 2> 2037402 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 2037403 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.ZkShardTerms Successful update of terms at /collections/collection1/terms/shard3 to Terms{values={core_node100=0, core_node92=0, core_node84=0}, version=6}
[junit4] 2> 2037411 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.RecoveryStrategy Updating version bucket highest from index after successful recovery.
[junit4] 2> 2037411 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1608450654522572800
[junit4] 2> 2037413 INFO (recoveryExecutor-4541-thread-1-processing-n:127.0.0.1:39820__evt%2Fzi x:collection1_shard3_replica_t99 c:collection1 s:shard3 r:core_node100) [n:127.0.0.1:39820__evt%2Fzi c:collection1 s:shard3 r:core_node100 x:collection1_shard3_replica_t99] o.a.s.c.RecoveryStrategy Finished recovery process, successful=[true]
[junit4] 2> 2037461 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:37053/solr
[junit4] 2> 2037464 INFO (zkConnectionManagerCallback-4560-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 2037482 INFO (zkConnectionManagerCallback-4562-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 2037488 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (11)
[junit4] 2> 2037504 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 2037504 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44632__evt%2Fzi
[junit4] 2> 2037506 INFO (zkCallback-4434-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037506 INFO (zkCallback-4402-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037506 INFO (zkCallback-4517-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037506 INFO (zkCallback-4493-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037506 INFO (zkCallback-4544-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037506 INFO (zkCallback-4466-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037506 INFO (zkCallback-4418-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037506 INFO (zkCallback-4376-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037507 INFO (zkCallback-4534-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037507 INFO (zkCallback-4450-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037507 INFO (zkCallback-4527-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037507 INFO (zkCallback-4411-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037513 INFO (zkCallback-4427-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037513 INFO (zkCallback-4395-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037513 INFO (zkCallback-4483-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037513 INFO (zkCallback-4443-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037513 INFO (zkCallback-4459-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037513 INFO (zkCallback-4500-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037513 INFO (zkCallback-4476-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037514 INFO (zkCallback-4551-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037514 INFO (zkCallback-4387-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037533 INFO (zkCallback-4369-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037555 INFO (zkCallback-4561-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037555 INFO (zkCallback-4510-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (11) -> (12)
[junit4] 2> 2037556 INFO (qtp2057734636-15357) [n:127.0.0.1:39411__evt%2Fzi c:collection1 s:shard3 r:core_node84 x:collection1_shard3_replica_t83] o.a.s.c.S.Request [collection1_shard3_replica_t83] webapp=/_evt/zi path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 2037557 INFO (indexFetcher-3021-thread-1) [ ] o.a.s.h.IndexFetcher Master's generation: 1
[junit4] 2> 2037557 INFO (indexFetcher-3021-thread-1) [ ] o.a.s.h.IndexFetcher Master's version: 0
[junit4] 2> 2037557 INFO (indexFetcher-3021-thread-1) [ ] o.a.s.h.IndexFetcher Slave's generation: 1
[junit4] 2> 2037557 INFO (indexFetcher-3021-thread-1) [ ] o.a.s.h.IndexFetcher Slave's version: 0
[junit4] 2> 2037557 INFO (indexFetcher-3021-thread-1) [ ] o.a.s.h.IndexFetcher New index in Master. Deleting mine...
[junit4] 2> 2037558 INFO (indexFetcher-3021-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@4d40d5b[collection1_shard3_replica_t91] main]
[junit4] 2> 2037559 INFO (searcherExecutor-3015-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard3_replica_t91] Registered new searcher Searcher@4d40d5b[collection1_shard3_replica_t91] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2037594 INFO (zkConnectionManagerCallback-4569-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 2037594 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (12)
[junit4] 2> 2037595 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:37053/solr ready
[junit4] 2> 2037596 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 2037665 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@15e8e80f
[junit4] 2> 2037681 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@15e8e80f
[junit4] 2> 2037681 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@15e8e80f
[junit4] 2> 2037683 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/../../../../../../../../../../home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsChaosMonkeyNothingIsSafeTest_F3CDB154F464C6A0-001/shard-11-001/cores
[junit4] 2> 2037889 INFO (qtp599385621-15700) [n:127.0.0.1:35891__evt%2Fzi ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :addreplica with params node=127.0.0.1:44632__evt%252Fzi&action=ADDREPLICA&collection=collection1&shard=shard4&type=TLOG&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 2037900 INFO (OverseerCollectionConfigSetProcessor-73124220234104836-127.0.0.1:42048__evt%2Fzi-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000022 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 2037900 INFO (OverseerThreadFactory-2924-thread-5) [ c:collection1 s:shard4 ] o.a.s.c.a.c.AddReplicaCmd Node Identified 127.0.0.1:44632__evt%2Fzi for creating new replica of shard shard4
[junit4] 2> 2037902 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&name=collection1_shard4_replica_t101&action=CREATE&collection=collection1&shard=shard4&wt=javabin&version=2&replicaType=TLOG
[junit4] 2> 2038934 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.0
[junit4] 2> 2038996 INFO (qtp1186484460-15406) [n:127.0.0.1:42172__evt%2Fzi c:collection1 s:shard4 r:core_node86 x:collection1_shard4_replica_t85] o.a.s.c.S.Request [collection1_shard4_replica_t85] webapp=/_evt/zi path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 2038996 INFO (indexFetcher-3046-thread-1) [ ] o.a.s.h.IndexFetcher Master's generation: 1
[junit4] 2> 2038997 INFO (indexFetcher-3046-thread-1) [ ] o.a.s.h.IndexFetcher Master's version: 0
[junit4] 2> 2038997 INFO (indexFetcher-3046-thread-1) [ ] o.a.s.h.IndexFetcher Slave's generation: 1
[junit4] 2> 2038997 INFO (indexFetcher-3046-thread-1) [ ] o.a.s.h.IndexFetcher Slave's version: 0
[junit4] 2> 2038997 INFO (indexFetcher-3046-thread-1) [ ] o.a.s.h.IndexFetcher New index in Master. Deleting mine...
[junit4] 2> 2038998 INFO (indexFetcher-3046-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@2c8532f6[collection1_shard4_replica_t93] main]
[junit4] 2> 2038999 INFO (searcherExecutor-3031-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard4_replica_t93] Registered new searcher Searcher@2c8532f6[collection1_shard4_replica_t93] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2039021 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.s.IndexSchema [collection1_shard4_replica_t101] Schema name=test
[junit4] 2> 2039203 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id
[junit4] 2> 2039223 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.CoreContainer Creating SolrCore 'collection1_shard4_replica_t101' using configuration from collection collection1, trusted=true
[junit4] 2> 2039224 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.collection1.shard4.replica_t101' (registry 'solr.core.collection1.shard4.replica_t101') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@15e8e80f
[junit4] 2> 2039224 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.HdfsDirectoryFactory solr.hdfs.home=hdfs://lucene2-us-west.apache.org:34266/solr_hdfs_home
[junit4] 2> 2039224 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.HdfsDirectoryFactory Solr Kerberos Authentication disabled
[junit4] 2> 2039224 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 2039224 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.SolrCore [[collection1_shard4_replica_t101] ] Opening new SolrCore at [/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsChaosMonkeyNothingIsSafeTest_F3CDB154F464C6A0-001/shard-11-001/cores/collection1_shard4_replica_t101], dataDir=[hdfs://lucene2-us-west.apache.org:34266/solr_hdfs_home/collection1/core_node102/data/]
[junit4] 2> 2039226 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://lucene2-us-west.apache.org:34266/solr_hdfs_home/collection1/core_node102/data/snapshot_metadata
[junit4] 2> 2039247 INFO (qtp482122760-15317) [n:127.0.0.1:36895__evt%2Fzi c:collection1 s:shard2 r:core_node82 x:collection1_shard2_replica_t81] o.a.s.c.S.Request [collection1_shard2_replica_t81] webapp=/_evt/zi path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 2039247 INFO (indexFetcher-3071-thread-1) [ ] o.a.s.h.IndexFetcher Master's generation: 1
[junit4] 2> 2039247 INFO (indexFetcher-3071-thread-1) [ ] o.a.s.h.IndexFetcher Master's version: 0
[junit4] 2> 2039247 INFO (indexFetcher-3071-thread-1) [ ] o.a.s.h.IndexFetcher Slave's generation: 1
[junit4] 2> 2039247 INFO (indexFetcher-3071-thread-1) [ ] o.a.s.h.IndexFetcher Slave's version: 0
[junit4] 2> 2039247 INFO (indexFetcher-3071-thread-1) [ ] o.a.s.h.IndexFetcher New index in Master. Deleting mine...
[junit4] 2> 2039257 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
[junit4] 2> 2039257 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [8388608] will allocate [1] slabs and use ~[8388608] bytes
[junit4] 2> 2039277 INFO (indexFetcher-3071-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@384fbaab[collection1_shard2_replica_t97] main]
[junit4] 2> 2039278 INFO (searcherExecutor-3063-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard2_replica_t97] Registered new searcher Searcher@384fbaab[collection1_shard2_replica_t97] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2039279 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.s.b.BlockDirectory Block cache on write is disabled
[junit4] 2> 2039280 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://lucene2-us-west.apache.org:34266/solr_hdfs_home/collection1/core_node102/data
[junit4] 2> 2039324 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://lucene2-us-west.apache.org:34266/solr_hdfs_home/collection1/core_node102/data/index
[junit4] 2> 2039401 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
[junit4] 2> 2039401 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [8388608] will allocate [1] slabs and use ~[8388608] bytes
[junit4] 2> 2039421 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.s.b.BlockDirectory Block cache on write is disabled
[junit4] 2> 2039422 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=32, maxMergeAtOnceExplicit=11, maxMergedSegmentMB=40.470703125, floorSegmentMB=0.3681640625, forceMergeDeletesPctAllowed=7.159042072915542, segmentsPerTier=46.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.204218408112585, deletesPctAllowed=33.772894637341295
[junit4] 2> 2039484 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:41416 is added to blk_1073741836_1012{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-708d0b63-3f3a-4e95-9e48-39921ca5284b:NORMAL:127.0.0.1:33970|RBW], ReplicaUC[[DISK]DS-a3ee9bf1-d8da-4bdf-b082-7f90f259c04b:NORMAL:127.0.0.1:41416|FINALIZED]]} size 0
[junit4] 2> 2039485 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:33970 is added to blk_1073741836_1012{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-a3ee9bf1-d8da-4bdf-b082-7f90f259c04b:NORMAL:127.0.0.1:41416|FINALIZED], ReplicaUC[[DISK]DS-008972ff-c8c4-4a10-84c8-0ce95e8cc016:NORMAL:127.0.0.1:33970|FINALIZED]]} size 0
[junit4] 2> 2039502 WARN (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,attributes = {initParams=a, name=/dump, class=DumpRequestHandler},args = {defaults={a=A,b=B}}}
[junit4] 2> 2039662 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.HdfsUpdateLog
[junit4] 2> 2039662 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 2039662 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.u.HdfsUpdateLog Initializing HdfsUpdateLog: tlogDfsReplication=2
[junit4] 2> 2039685 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.u.CommitTracker Hard AutoCommit: if uncommited for 15000ms;
[junit4] 2> 2039685 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 2039689 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.MockRandomMergePolicy: org.apache.lucene.index.MockRandomMergePolicy@33907a9c
[junit4] 2> 2039724 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.s.SolrIndexSearcher Opening [Searcher@5e658b11[collection1_shard4_replica_t101] main]
[junit4] 2> 2039725 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 2039726 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 2039726 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 2039753 INFO (searcherExecutor-3095-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.SolrCore [collection1_shard4_replica_t101] Registered new searcher Searcher@5e658b11[collection1_shard4_replica_t101] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2039753 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1608450656978337792
[junit4] 2> 2039765 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.ZkShardTerms Successful update of terms at /collections/collection1/terms/shard4 to Terms{values={core_node94=0, core_node86=0, core_node102=0}, version=4}
[junit4] 2> 2039767 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.c.ZkController Core needs to recover:collection1_shard4_replica_t101
[junit4] 2> 2039767 INFO (updateExecutor-4557-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.u.DefaultSolrCoreState Running recovery
[junit4] 2> 2039768 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.c.RecoveryStrategy Starting recovery process. recoveringAfterStartup=true
[junit4] 2> 2039781 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.c.RecoveryStrategy ###### startupVersions=[[]]
[junit4] 2> 2039781 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.c.ZkController collection1_shard4_replica_t101 stopping background replication from leader
[junit4] 2> 2039783 INFO (qtp1186484460-15402) [n:127.0.0.1:42172__evt%2Fzi c:collection1 s:shard4 r:core_node86 x:collection1_shard4_replica_t85] o.a.s.c.S.Request [collection1_shard4_replica_t85] webapp=/_evt/zi path=/admin/ping params={wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 2039783 INFO (qtp1186484460-15402) [n:127.0.0.1:42172__evt%2Fzi c:collection1 s:shard4 r:core_node86 x:collection1_shard4_replica_t85] o.a.s.c.S.Request [collection1_shard4_replica_t85] webapp=/_evt/zi path=/admin/ping params={wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 2039783 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[collection1_shard4_replica_t101]
[junit4] 2> 2039788 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.u.UpdateLog Starting to buffer updates. HDFSUpdateLog{state=ACTIVE, tlog=null}
[junit4] 2> 2039788 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.c.RecoveryStrategy Publishing state of core [collection1_shard4_replica_t101] as recovering, leader is [http://127.0.0.1:42172/_evt/zi/collection1_shard4_replica_t85/] and I am [http://127.0.0.1:44632/_evt/zi/collection1_shard4_replica_t101/]
[junit4] 2> 2039788 INFO (qtp1165279809-15804) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 x:collection1_shard4_replica_t101] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&name=collection1_shard4_replica_t101&action=CREATE&collection=collection1&shard=shard4&wt=javabin&version=2&replicaType=TLOG} status=0 QTime=1886
[junit4] 2> 2039811 INFO (qtp599385621-15700) [n:127.0.0.1:35891__evt%2Fzi c:collection1 ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={node=127.0.0.1:44632__evt%252Fzi&action=ADDREPLICA&collection=collection1&shard=shard4&type=TLOG&wt=javabin&version=2} status=0 QTime=1921
[junit4] 2> 2039811 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.c.ZkShardTerms Successful update of terms at /collections/collection1/terms/shard4 to Terms{values={core_node86=0, core_node102_recovering=0, core_node94=0, core_node102=0}, version=5}
[junit4] 2> 2039826 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://127.0.0.1:42172/_evt/zi]; [WaitForState: action=PREPRECOVERY&core=collection1_shard4_replica_t85&nodeName=127.0.0.1:44632__evt%252Fzi&coreNodeName=core_node102&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
[junit4] 2> 2039826 INFO (qtp1186484460-15409) [n:127.0.0.1:42172__evt%2Fzi x:collection1_shard4_replica_t85] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node102, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true, maxTime: 183 s
[junit4] 2> 2039827 INFO (qtp1186484460-15409) [n:127.0.0.1:42172__evt%2Fzi x:collection1_shard4_replica_t85] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=collection1, shard=shard4, thisCore=collection1_shard4_replica_t85, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=down, localState=active, nodeName=127.0.0.1:44632__evt%2Fzi, coreNodeName=core_node102, onlyIfActiveCheckResult=false, nodeProps: core_node102:{"core":"collection1_shard4_replica_t101","base_url":"http://127.0.0.1:44632/_evt/zi","node_name":"127.0.0.1:44632__evt%2Fzi","state":"down","type":"TLOG"}
[junit4] 2> 2039902 INFO (OverseerCollectionConfigSetProcessor-73124220234104836-127.0.0.1:42048__evt%2Fzi-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000024 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 2040164 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 12 in directory /home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsChaosMonkeyNothingIsSafeTest_F3CDB154F464C6A0-001/shard-12-001 of type TLOG
[junit4] 2> 2040165 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.e.j.s.Server jetty-9.4.11.v20180605; built: 2018-06-05T18:24:03.829Z; git: d5fc0523cfa96bfebfbda19606cad384d772f04c; jvm 1.8.0_172-b11
[junit4] 2> 2040166 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 2040166 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 2040166 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.e.j.s.session node0 Scavenging every 660000ms
[junit4] 2> 2040166 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@2a392947{/_evt/zi,null,AVAILABLE}
[junit4] 2> 2040193 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@e8eb8c{HTTP/1.1,[http/1.1]}{127.0.0.1:44084}
[junit4] 2> 2040193 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.e.j.s.Server Started @2040258ms
[junit4] 2> 2040193 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=hdfs://lucene2-us-west.apache.org:34266/hdfs__lucene2-us-west.apache.org_34266__home_jenkins_jenkins-slave_workspace_Lucene-Solr-repro_solr_build_solr-core_test_J1_temp_solr.cloud.hdfs.HdfsChaosMonkeyNothingIsSafeTest_F3CDB154F464C6A0-001_tempDir-002_jetty12, replicaType=TLOG, solrconfig=solrconfig.xml, hostContext=/_evt/zi, hostPort=44084, coreRootDirectory=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/../../../../../../../../../../home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsChaosMonkeyNothingIsSafeTest_F3CDB154F464C6A0-001/shard-12-001/cores}
[junit4] 2> 2040193 ERROR (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 2040194 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
[junit4] 2> 2040194 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 8.0.0
[junit4] 2> 2040194 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 2040194 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 2040194 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-08-10T21:54:41.208Z
[junit4] 2> 2040204 INFO (zkConnectionManagerCallback-4573-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 2040205 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 2040205 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsChaosMonkeyNothingIsSafeTest_F3CDB154F464C6A0-001/shard-12-001/solr.xml
[junit4] 2> 2040209 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored
[junit4] 2> 2040209 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored
[junit4] 2> 2040210 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@15e8e80f, but no JMX reporters were configured - adding default JMX reporter.
[junit4] 2> 2040576 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:37053/solr
[junit4] 2> 2040590 INFO (zkConnectionManagerCallback-4577-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 2040592 INFO (zkConnectionManagerCallback-4579-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 2040622 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (12)
[junit4] 2> 2040626 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 2040626 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44084__evt%2Fzi
[junit4] 2> 2040627 INFO (zkCallback-4510-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4493-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4411-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4387-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4443-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4544-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4517-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4561-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4402-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4568-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4527-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4551-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4376-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4483-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4476-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4418-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4500-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4534-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4466-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4459-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4450-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040629 INFO (zkCallback-4434-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040628 INFO (zkCallback-4395-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040629 INFO (zkCallback-4427-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040629 INFO (zkCallback-4369-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040656 INFO (zkCallback-4578-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (12) -> (13)
[junit4] 2> 2040680 INFO (zkConnectionManagerCallback-4586-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 2040681 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (13)
[junit4] 2> 2040682 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:37053/solr ready
[junit4] 2> 2040695 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 2040740 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@15e8e80f
[junit4] 2> 2040756 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@15e8e80f
[junit4] 2> 2040756 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@15e8e80f
[junit4] 2> 2040758 INFO (TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/../../../../../../../../../../home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/solr/build/solr-core/test/J1/temp/solr.cloud.hdfs.HdfsChaosMonkeyNothingIsSafeTest_F3CDB154F464C6A0-001/shard-12-001/cores
[junit4] 2> 2040827 INFO (qtp1186484460-15409) [n:127.0.0.1:42172__evt%2Fzi x:collection1_shard4_replica_t85] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=collection1, shard=shard4, thisCore=collection1_shard4_replica_t85, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=recovering, localState=active, nodeName=127.0.0.1:44632__evt%2Fzi, coreNodeName=core_node102, onlyIfActiveCheckResult=false, nodeProps: core_node102:{"dataDir":"hdfs://lucene2-us-west.apache.org:34266/solr_hdfs_home/collection1/core_node102/data/","base_url":"http://127.0.0.1:44632/_evt/zi","node_name":"127.0.0.1:44632__evt%2Fzi","type":"TLOG","ulogDir":"hdfs://lucene2-us-west.apache.org:34266/solr_hdfs_home/collection1/core_node102/data/tlog","core":"collection1_shard4_replica_t101","shared_storage":"true","state":"recovering"}
[junit4] 2> 2040827 INFO (qtp1186484460-15409) [n:127.0.0.1:42172__evt%2Fzi x:collection1_shard4_replica_t85] o.a.s.h.a.PrepRecoveryOp Waited coreNodeName: core_node102, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4] 2> 2040827 INFO (qtp1186484460-15409) [n:127.0.0.1:42172__evt%2Fzi x:collection1_shard4_replica_t85] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={nodeName=127.0.0.1:44632__evt%252Fzi&onlyIfLeaderActive=true&core=collection1_shard4_replica_t85&coreNodeName=core_node102&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=0 QTime=1000
[junit4] 2> 2041004 INFO (qtp345789901-15448) [n:127.0.0.1:35563__evt%2Fzi ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :addreplica with params node=127.0.0.1:44084__evt%252Fzi&action=ADDREPLICA&collection=collection1&shard=shard1&type=TLOG&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 2041006 INFO (OverseerThreadFactory-2924-thread-5) [ c:collection1 s:shard1 ] o.a.s.c.a.c.AddReplicaCmd Node Identified 127.0.0.1:44084__evt%2Fzi for creating new replica of shard shard1
[junit4] 2> 2041009 INFO (qtp2087129708-15855) [n:127.0.0.1:44084__evt%2Fzi x:collection1_shard1_replica_t103] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&name=collection1_shard1_replica_t103&action=CREATE&collection=collection1&shard=shard1&wt=javabin&version=2&replicaType=TLOG
[junit4] 2> 2041328 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.c.RecoveryStrategy Starting Replication Recovery.
[junit4] 2> 2041328 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.c.RecoveryStrategy Attempting to replicate from [http://127.0.0.1:42172/_evt/zi/collection1_shard4_replica_t85/].
[junit4] 2> 2041330 INFO (qtp1186484460-15402) [n:127.0.0.1:42172__evt%2Fzi c:collection1 s:shard4 r:core_node86 x:collection1_shard4_replica_t85] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1608450658631942144,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 2041330 INFO (qtp1186484460-15402) [n:127.0.0.1:42172__evt%2Fzi c:collection1 s:shard4 r:core_node86 x:collection1_shard4_replica_t85] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 2041331 INFO (qtp1186484460-15402) [n:127.0.0.1:42172__evt%2Fzi c:collection1 s:shard4 r:core_node86 x:collection1_shard4_replica_t85] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 2041331 INFO (qtp1186484460-15402) [n:127.0.0.1:42172__evt%2Fzi c:collection1 s:shard4 r:core_node86 x:collection1_shard4_replica_t85] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard4_replica_t85] webapp=/_evt/zi path=/update params={waitSearcher=true&openSearcher=false&commit=true&softCommit=false&commit_end_point=true&wt=javabin&version=2}{commit=} 0 1
[junit4] 2> 2041333 INFO (qtp1186484460-15406) [n:127.0.0.1:42172__evt%2Fzi c:collection1 s:shard4 r:core_node86 x:collection1_shard4_replica_t85] o.a.s.c.S.Request [collection1_shard4_replica_t85] webapp=/_evt/zi path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 2041333 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.h.IndexFetcher Master's generation: 1
[junit4] 2> 2041333 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.h.IndexFetcher Master's version: 0
[junit4] 2> 2041333 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.h.IndexFetcher Slave's generation: 1
[junit4] 2> 2041333 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.h.IndexFetcher Slave's version: 0
[junit4] 2> 2041333 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.h.IndexFetcher New index in Master. Deleting mine...
[junit4] 2> 2041348 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.s.SolrIndexSearcher Opening [Searcher@415cdb27[collection1_shard4_replica_t101] main]
[junit4] 2> 2041350 INFO (searcherExecutor-3095-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.c.SolrCore [collection1_shard4_replica_t101] Registered new searcher Searcher@415cdb27[collection1_shard4_replica_t101] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2041350 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.c.RecoveryStrategy Replication Recovery was successful.
[junit4] 2> 2041350 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.c.RecoveryStrategy Registering as Active after recovery.
[junit4] 2> 2041350 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_node102 x:collection1_shard4_replica_t101] o.a.s.c.ZkController collection1_shard4_replica_t101 starting background replication from leader
[junit4] 2> 2041350 INFO (recoveryExecutor-4558-thread-1-processing-n:127.0.0.1:44632__evt%2Fzi x:collection1_shard4_replica_t101 c:collection1 s:shard4 r:core_node102) [n:127.0.0.1:44632__evt%2Fzi c:collection1 s:shard4 r:core_n
[...truncated too long message...]
pache.zookeeper.client.StaticHostProvider.next(StaticHostProvider.java:105)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$SendThread.startConnect(ClientCnxn.java:1000)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1063)
[junit4] 2> 2) Thread[id=15509, name=zkConnectionManagerCallback-4396-thread-1, state=WAITING, group=TGRP-HdfsChaosMonkeyNothingIsSafeTest]
[junit4] 2> at sun.misc.Unsafe.park(Native Method)
[junit4] 2> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
[junit4] 2> at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene70): {rnd_b=BlockTreeOrds(blocksize=128), a_t=PostingsFormat(name=Asserting), id=BlockTreeOrds(blocksize=128)}, docValues:{rnd_b=DocValuesFormat(name=Direct), _version_=DocValuesFormat(name=Lucene70), a_t=DocValuesFormat(name=Lucene70), a_i=DocValuesFormat(name=Direct), id=DocValuesFormat(name=Direct)}, maxPointsInLeafNode=1473, maxMBSortInHeap=5.390819030422193, sim=Asserting(org.apache.lucene.search.similarities.AssertingSimilarity@50a16b8), locale=lt, timezone=Africa/Porto-Novo
[junit4] 2> NOTE: Linux 4.4.0-112-generic amd64/Oracle Corporation 1.8.0_172 (64-bit)/cpus=4,threads=4,free=146614016,total=531628032
[junit4] 2> NOTE: All tests run in this JVM: [CdcrReplicationDistributedZkTest, HdfsRestartWhileUpdatingTest, HdfsChaosMonkeyNothingIsSafeTest]
[junit4] 2> NOTE: download the large Jenkins line-docs file by running 'ant get-jenkins-line-docs' in the lucene directory.
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=HdfsChaosMonkeyNothingIsSafeTest -Dtests.seed=F3CDB154F464C6A0 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.badapples=true -Dtests.linedocsfile=/home/jenkins/jenkins-slave/workspace/Lucene-Solr-BadApples-NightlyTests-master/test-data/enwiki.random.lines.txt -Dtests.locale=lt -Dtests.timezone=Africa/Porto-Novo -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[junit4] ERROR 0.00s J2 | HdfsChaosMonkeyNothingIsSafeTest (suite) <<<
[junit4] > Throwable #1: com.carrotsearch.randomizedtesting.ThreadLeakError: 4 threads leaked from SUITE scope at org.apache.solr.cloud.hdfs.HdfsChaosMonkeyNothingIsSafeTest:
[junit4] > 1) Thread[id=15507, name=TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]-SendThread(127.0.0.1:38268), state=TIMED_WAITING, group=TGRP-HdfsChaosMonkeyNothingIsSafeTest]
[junit4] > at java.lang.Thread.sleep(Native Method)
[junit4] > at org.apache.zookeeper.client.StaticHostProvider.next(StaticHostProvider.java:105)
[junit4] > at org.apache.zookeeper.ClientCnxn$SendThread.startConnect(ClientCnxn.java:1000)
[junit4] > at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1063)
[junit4] > 2) Thread[id=15508, name=TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]-EventThread, state=WAITING, group=TGRP-HdfsChaosMonkeyNothingIsSafeTest]
[junit4] > at sun.misc.Unsafe.park(Native Method)
[junit4] > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
[junit4] > at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
[junit4] > at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
[junit4] > at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:502)
[junit4] > 3) Thread[id=15506, name=Connection evictor, state=TIMED_WAITING, group=TGRP-HdfsChaosMonkeyNothingIsSafeTest]
[junit4] > at java.lang.Thread.sleep(Native Method)
[junit4] > at org.apache.http.impl.client.IdleConnectionEvictor$1.run(IdleConnectionEvictor.java:66)
[junit4] > at java.lang.Thread.run(Thread.java:748)
[junit4] > 4) Thread[id=15509, name=zkConnectionManagerCallback-4396-thread-1, state=WAITING, group=TGRP-HdfsChaosMonkeyNothingIsSafeTest]
[junit4] > at sun.misc.Unsafe.park(Native Method)
[junit4] > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
[junit4] > at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
[junit4] > at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
[junit4] > at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
[junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
[junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[junit4] > at java.lang.Thread.run(Thread.java:748)
[junit4] > at __randomizedtesting.SeedInfo.seed([F3CDB154F464C6A0]:0)Throwable #2: com.carrotsearch.randomizedtesting.ThreadLeakError: There are still zombie threads that couldn't be terminated:
[junit4] > 1) Thread[id=15507, name=TEST-HdfsChaosMonkeyNothingIsSafeTest.test-seed#[F3CDB154F464C6A0]-SendThread(127.0.0.1:38268), state=TIMED_WAITING, group=TGRP-HdfsChaosMonkeyNothingIsSafeTest]
[junit4] > at java.lang.Thread.sleep(Native Method)
[junit4] > at org.apache.zookeeper.client.StaticHostProvider.next(StaticHostProvider.java:105)
[junit4] > at org.apache.zookeeper.ClientCnxn$SendThread.startConnect(ClientCnxn.java:1000)
[junit4] > at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1063)
[junit4] > 2) Thread[id=15509, name=zkConnectionManagerCallback-4396-thread-1, state=WAITING, group=TGRP-HdfsChaosMonkeyNothingIsSafeTest]
[junit4] > at sun.misc.Unsafe.park(Native Method)
[junit4] > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
[junit4] > at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
[junit4] > at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
[junit4] > at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
[junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
[junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[junit4] > at java.lang.Thread.run(Thread.java:748)
[junit4] > at __randomizedtesting.SeedInfo.seed([F3CDB154F464C6A0]:0)
[junit4] Completed [15/15 (6!)] on J2 in 706.99s, 1 test, 3 errors <<< FAILURES!
[junit4]
[junit4]
[junit4] Tests with failures [seed: F3CDB154F464C6A0] (first 10 out of 33):
[junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testBatchAddsWithDelete
[junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testBatchAddsWithDelete
[junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testBatchAddsWithDelete
[junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testBufferOnNonLeader
[junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testBufferOnNonLeader
[junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testBufferOnNonLeader
[junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testOps
[junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testOps
[junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testOps
[junit4] - org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest.testReplicationAfterLeaderChange
[junit4]
[junit4]
[junit4] JVM J0: 0.81 .. 2032.48 = 2031.67s
[junit4] JVM J1: 0.75 .. 2508.04 = 2507.29s
[junit4] JVM J2: 0.76 .. 2770.25 = 2769.49s
[junit4] Execution time total: 46 minutes 10 seconds
[junit4] Tests summary: 15 suites, 65 tests, 6 suite-level errors, 30 errors, 27 ignored
BUILD FAILED
/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/lucene/common-build.xml:1568: The following error occurred while executing this line:
/home/jenkins/jenkins-slave/workspace/Lucene-Solr-repro/lucene/common-build.xml:1092: There were test failures: 15 suites, 65 tests, 6 suite-level errors, 30 errors, 27 ignored [seed: F3CDB154F464C6A0]
Total time: 46 minutes 12 seconds
[repro] Setting last failure code to 256
[repro] Failures:
[repro] 0/5 failed: org.apache.solr.cloud.hdfs.HdfsRestartWhileUpdatingTest
[repro] 3/5 failed: org.apache.solr.cloud.cdcr.CdcrReplicationDistributedZkTest
[repro] 3/5 failed: org.apache.solr.cloud.hdfs.HdfsChaosMonkeyNothingIsSafeTest
[repro] 4/5 failed: org.apache.lucene.document.TestLatLonLineShapeQueries
[repro] git checkout cdc0959afcc3d64cbc0f42951964979680b080a0
Previous HEAD position was 9c02bf0... LUCENE-8451: Add disabled regression test
HEAD is now at cdc0959... Ref Guide: small typos; i.e. and e.g. cleanups
[repro] Exiting with code 256
Archiving artifacts
Recording test results
Build step 'Publish JUnit test result report' changed build result to UNSTABLE
Email was triggered for: Unstable (Test Failures)
Sending email for trigger: Unstable (Test Failures)