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)
--------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org